Rewrite logging settings and AppLogger

Author: davegaeddert

plain-observer/plain/observer/config.py

@@ -3,7 +3,7 @@
 from opentelemetry.sdk.trace import TracerProvider
 from opentelemetry.semconv.attributes import service_attributes
 
-from plain.logs.loggers import app_logger
+from plain.logs import app_logger
 from plain.packages import PackageConfig, register_config
 from plain.runtime import settings
 

plain-observer/plain/observer/otel.py

@@ -10,7 +10,7 @@
 from opentelemetry.trace import SpanKind, format_span_id, format_trace_id
 
 from plain.http.cookie import unsign_cookie_value
-from plain.logs.loggers import app_logger
+from plain.logs import app_logger
 from plain.models.otel import suppress_db_tracing
 from plain.runtime import settings
 

plain-worker/plain/worker/middleware.py

@@ -6,12 +6,7 @@ def __init__(self, run_job):
         self.run_job = run_job
 
     def __call__(self, job):
-        app_logger.kv.context["job_request_uuid"] = str(job.job_request_uuid)
-        app_logger.kv.context["job_uuid"] = str(job.uuid)
-
-        job_result = self.run_job(job)
-
-        app_logger.kv.context.pop("job_request_uuid", None)
-        app_logger.kv.context.pop("job_uuid", None)
-
-        return job_result
+        with app_logger.with_context(
+            job_request_uuid=str(job.job_request_uuid), job_uuid=str(job.uuid)
+        ):
+            return self.run_job(job)

plain/plain/csrf/middleware.py

@@ -3,7 +3,7 @@
 from urllib.parse import urlparse
 
 from plain.exceptions import DisallowedHost
-from plain.logs import log_response
+from plain.logs.utils import log_response
 from plain.runtime import settings
 
 from .views import CsrfFailureView

plain/plain/internal/handlers/base.py

@@ -5,7 +5,7 @@
 from opentelemetry.semconv.attributes import http_attributes, url_attributes
 
 from plain.exceptions import ImproperlyConfigured
-from plain.logs import log_response
+from plain.logs.utils import log_response
 from plain.runtime import settings
 from plain.urls import get_resolver
 from plain.utils.module_loading import import_string

plain/plain/internal/handlers/exception.py

@@ -12,7 +12,7 @@
 )
 from plain.http import Http404, ResponseServerError
 from plain.http.multipartparser import MultiPartParserError
-from plain.logs import log_response
+from plain.logs.utils import log_response
 from plain.runtime import settings
 from plain.utils.module_loading import import_string
 from plain.views.errors import ErrorView

plain/plain/logs/README.md

@@ -4,7 +4,10 @@
 
 - [Overview](#overview)
 - [`app_logger`](#app_logger)
-- [`app_logger.kv`](#app_loggerkv)
+- [Output formats](#output-formats)
+- [Context management](#context-management)
+- [Debug mode](#debug-mode)
+- [Advanced usage](#advanced-usage)
 - [Logging settings](#logging-settings)
 
 ## Overview
@@ -13,49 +16,124 @@ In Python, configuring logging can be surprisingly complex. For most use cases,
 
 By default, both the `plain` and `app` loggers are set to the `INFO` level. You can quickly change this by using the `PLAIN_LOG_LEVEL` and `APP_LOG_LEVEL` environment variables.
 
+The `app_logger` supports multiple output formats and provides a friendly kwargs-based API for structured logging.
+
 ## `app_logger`
 
-The `app_logger` is a pre-configured logger you can use inside your app code.
+The `app_logger` is an enhanced logger that supports kwargs-style logging and multiple output formats.
 
 ```python
 from plain.logs import app_logger
 
 
 def example_function():
-    app_logger.info("Hey!")
+    # Basic logging
+    app_logger.info("User logged in")
+
+    # With structured context data (explicit **context parameter)
+    app_logger.info("User action", user_id=123, action="login", success=True)
+
+    # All log levels support context parameters
+    app_logger.debug("Debug info", step="validation", count=5)
+    app_logger.warning("Rate limit warning", user_id=456, limit_exceeded=True)
+    app_logger.error("Database error", error_code=500, table="users")
+
+    # Standard logging parameters with context
+    try:
+        risky_operation()
+    except Exception:
+        app_logger.error(
+            "Operation failed",
+            exc_info=True,  # Include exception traceback
+            stack_info=True,  # Include stack trace
+            user_id=789,
+            operation="risky_operation"
+        )
 ```
 
-## `app_logger.kv`
+## Output formats
+
+The `app_logger` supports three output formats controlled by the `APP_LOG_FORMAT` environment variable:
 
-The key-value logging format is popular for outputting more structured logs that are still human-readable.
+### Key-Value format (default)
+
+```bash
+export APP_LOG_FORMAT=keyvalue  # or leave unset for default
+```
+
+```
+[INFO] User action user_id=123 action=login success=True
+[ERROR] Database error error_code=500 table=users
+```
+
+### JSON format
+
+```bash
+export APP_LOG_FORMAT=json
+```
+
+```json
+{"timestamp": "2024-01-01 12:00:00,123", "level": "INFO", "message": "User action", "user_id": 123, "action": "login", "success": true}
+{"timestamp": "2024-01-01 12:00:01,456", "level": "ERROR", "message": "Database error", "error_code": 500, "table": "users"}
+```
+
+### Standard format
+
+```bash
+export APP_LOG_FORMAT=standard
+```
+
+```
+[INFO] User action
+[ERROR] Database error
+```
+
+Note: In standard format, the context kwargs are ignored and not displayed.
+
+## Context management
+
+The `app_logger` provides powerful context management for adding data to multiple log statements.
+
+### Persistent context
+
+Use the `context` dict to add data that persists across log calls:
 
 ```python
-from plain.logs import app_logger
+# Set persistent context
+app_logger.context["user_id"] = 123
+app_logger.context["request_id"] = "abc456"
 
+app_logger.info("Started processing")      # Includes user_id and request_id
+app_logger.info("Validation complete")     # Includes user_id and request_id
+app_logger.info("Processing finished")     # Includes user_id and request_id
 
-def example_function():
-    app_logger.kv("Example log line with", example_key="example_value")
+# Clear context
+app_logger.context.clear()
 ```
 
-## Logging settings
+### Temporary context
 
-You can further configure your logging with `settings.LOGGING`.
+Use `include_context()` for temporary context that only applies within a block:
 
 ```python
-# app/settings.py
-LOGGING = {
-    "version": 1,
-    "disable_existing_loggers": False,
-    "handlers": {
-        "console": {
-            "class": "logging.StreamHandler",
-        },
-    },
-    "loggers": {
-        "mylogger": {
-            "handlers": ["console"],
-            "level": "DEBUG",
-        },
-    },
-}
+app_logger.context["user_id"] = 123  # Persistent
+
+with app_logger.include_context(operation="payment", transaction_id="txn789"):
+    app_logger.info("Payment started")     # Has user_id, operation, transaction_id
+    app_logger.info("Payment validated")   # Has user_id, operation, transaction_id
+
+app_logger.info("Payment complete")        # Only has user_id
+```
+
+## Debug mode
+
+The `force_debug()` context manager allows temporarily enabling DEBUG level logging:
+
+```python
+# Debug messages might not show at INFO level
+app_logger.debug("This might not appear")
+
+# Temporarily enable debug logging
+with app_logger.force_debug():
+    app_logger.debug("This will definitely appear", extra_data="debug_info")
 ```

plain/plain/logs/__init__.py

@@ -1,5 +1,3 @@
-from .configure import configure_logging
 from .loggers import app_logger
-from .utils import log_response
 
-__all__ = ["app_logger", "log_response", "configure_logging"]
+__all__ = ["app_logger"]

plain/plain/logs/configure.py

@@ -1,44 +1,36 @@
 import logging
-import logging.config
-from os import environ
-
-
-def configure_logging(logging_settings):
-    # Load the defaults
-    default_logging = {
-        "version": 1,
-        "disable_existing_loggers": False,
-        "formatters": {
-            "simple": {
-                "format": "[%(levelname)s] %(message)s",
-            },
-        },
-        "handlers": {
-            "plain_console": {
-                "level": "DEBUG",
-                "class": "logging.StreamHandler",
-                "formatter": "simple",
-            },
-            "app_console": {
-                "level": "DEBUG",
-                "class": "logging.StreamHandler",
-                "formatter": "simple",
-            },
-        },
-        "loggers": {
-            "plain": {
-                "handlers": ["plain_console"],
-                "level": environ.get("PLAIN_LOG_LEVEL", "INFO"),
-            },
-            "app": {
-                "handlers": ["app_console"],
-                "level": environ.get("APP_LOG_LEVEL", "INFO"),
-                "propagate": False,
-            },
-        },
-    }
-    logging.config.dictConfig(default_logging)
-
-    # Then customize it from settings
-    if logging_settings:
-        logging.config.dictConfig(logging_settings)
+
+from .formatters import JSONFormatter, KeyValueFormatter
+
+
+def configure_logging(*, plain_log_level, app_log_level, app_log_format):
+    # Create and configure the plain logger (uses standard Logger, not AppLogger)
+    plain_logger = logging.Logger("plain")
+    plain_logger.setLevel(plain_log_level)
+    plain_handler = logging.StreamHandler()
+    plain_handler.setFormatter(logging.Formatter("[%(levelname)s] %(message)s"))
+    plain_logger.addHandler(plain_handler)
+    plain_logger.propagate = False
+    logging.root.manager.loggerDict["plain"] = plain_logger
+
+    # Configure the existing app_logger
+    from .loggers import app_logger
+
+    app_logger.setLevel(app_log_level)
+    app_logger.propagate = False
+
+    app_handler = logging.StreamHandler()
+    match app_log_format:
+        case "json":
+            app_handler.setFormatter(JSONFormatter("%(json)s"))
+        case "keyvalue":
+            app_handler.setFormatter(
+                KeyValueFormatter("[%(levelname)s] %(message)s %(keyvalue)s")
+            )
+        case _:
+            app_handler.setFormatter(logging.Formatter("[%(levelname)s] %(message)s"))
+
+    app_logger.addHandler(app_handler)
+
+    # Register the app_logger in the logging system so getLogger("app") returns it
+    logging.root.manager.loggerDict["app"] = app_logger

plain/plain/logs/debug.py

@@ -0,0 +1,36 @@
+import logging
+import threading
+
+
+class DebugMode:
+    """Context manager to temporarily set DEBUG level on a logger with reference counting."""
+
+    def __init__(self, logger):
+        self.logger = logger
+        self.original_level = None
+        self._ref_count = 0
+        self._lock = threading.Lock()
+
+    def __enter__(self):
+        """Store original level and set to DEBUG."""
+        self.start()
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        """Restore original level."""
+        self.end()
+
+    def start(self):
+        """Enable DEBUG logging level."""
+        with self._lock:
+            if self._ref_count == 0:
+                self.original_level = self.logger.level
+                self.logger.setLevel(logging.DEBUG)
+            self._ref_count += 1
+
+    def end(self):
+        """Restore original logging level."""
+        with self._lock:
+            self._ref_count = max(0, self._ref_count - 1)
+            if self._ref_count == 0:
+                self.logger.setLevel(self.original_level)