team-tryouts/app/logging_config.py

"""Structured logging configuration for the Team Tryouts application.

This module configures rotating file handlers for application logs,
with separate files for errors, authentication events, and general logs.
Sensitive data (passwords, tokens) is automatically filtered out.

Usage:
    from logging_config import configure_logging
    configure_logging(app)
"""

import logging
import os
import re
from logging.handlers import RotatingFileHandler

from app.storage import logs_root

#: Value used when a record is emitted outside a request — startup, the
#: Discord bot thread, the scheduler. Short and obviously not an id, so a
#: grep for one never matches it by accident.
NO_REQUEST = '-'


class RequestIdFilter(logging.Filter):
    """Stamp every record with the id of the request that produced it.

    Without this, a 500 in errors.log and the six lines in app.log that led
    to it are related only by their timestamps, which is not a relation when
    the server is handling more than one request at a time (OBS-005).

    The id is generated per request and never read from an inbound header.
    Accepting one would be convenient for tracing across nginx, and it would
    also let any caller write arbitrary text — newlines included — into the
    log file, which is how a log gets forged rather than read. There is no
    trusted proxy to take it from while OPS-002 is open.
    """

    def filter(self, record):
        record.request_id = NO_REQUEST
        try:
            from flask import g, has_request_context

            if has_request_context():
                record.request_id = g.get('request_id', NO_REQUEST)
        except Exception:  # noqa: BLE001 — logging must never be the thing that fails
            pass
        return True


class SensitiveDataFilter(logging.Filter):
    """Logging filter that redacts sensitive information from log messages.

    Filters out: passwords, API keys, session tokens, and other secrets
    that might accidentally be logged.
    """

    # Patterns to redact
    SENSITIVE_PATTERNS = [
        (
            re.compile(
                r'(?:password|passwd|secret|token|api[_-]?key)\s*[:=]\s*[^\s,;)]+', re.IGNORECASE
            ),
            '[REDACTED]',
        ),
        (
            re.compile(
                r'(?:password|passwd|secret|token|api[_-]?key)\s*[:=]\s*"[^"]*"', re.IGNORECASE
            ),
            lambda m: m.group(0).split('=')[0] + '="[REDACTED]"',
        ),
        (re.compile(r'Authorization[:\s]+[^\s]+', re.IGNORECASE), 'Authorization: [REDACTED]'),
        (re.compile(r'Bearer\s+[^\s]+', re.IGNORECASE), 'Bearer [REDACTED]'),
    ]

    def filter(self, record):
        """Apply redaction to the log record's fully rendered message.

        The record is rendered first (msg % args) and the result stored back
        as msg with args cleared. Redacting record.msg alone would miss almost
        everything: this codebase logs with %s placeholders, so the sensitive
        value lives in record.args while record.msg holds only the format
        string.

        Args:
            record: The log record to filter.

        Returns:
            bool: Always True (never drops records, only redacts).
        """
        try:
            rendered = record.getMessage()
        except Exception:  # noqa: BLE001 — see below; this one cannot log its own failure
            # A malformed format string must not lose the record entirely.
            # Nor can it be logged: this runs inside a filter, and logging
            # from here re-enters the same filter on the new record. The
            # traceback BLE001 normally asks for is the one thing this
            # handler must not produce, hence the waiver.
            return True

        for pattern, replacement in self.SENSITIVE_PATTERNS:
            rendered = pattern.sub(replacement, rendered)

        record.msg = rendered
        record.args = ()
        return True


def configure_logging(app):
    """Configure structured logging for the Flask application.

    Sets up three rotating file handlers:
        - errors.log: ERROR and CRITICAL level messages
        - auth.log: Authentication-related events (INFO and above)
        - app.log: All application logs (DEBUG and above, configurable)

    Also configures console output for development.

    Args:
        app: The Flask application instance to configure logging for.
    """
    # Anchored on the project, not on the working directory (OBS-006). The
    # old form put the logs wherever the process happened to be started
    # from, so a service restarted by hand from another directory quietly
    # began writing somewhere else — and the file you go looking at when
    # something is wrong is the one that must not move.
    log_dir = logs_root()
    os.makedirs(log_dir, exist_ok=True)

    # Remove default Flask handlers to avoid duplicate logging
    app.logger.handlers.clear()

    # Set base log level from environment (default: INFO)
    log_level_name = os.getenv('LOG_LEVEL', 'INFO').upper()
    log_level = getattr(logging, log_level_name, logging.INFO)
    app.logger.setLevel(log_level)

    # Create the sensitive data filter
    sensitive_filter = SensitiveDataFilter()
    request_id_filter = RequestIdFilter()

    # Formatter with timestamp, level, module, request id, and message.
    #
    # request_id comes from RequestIdFilter, which is attached to every
    # handler below. A handler that formats with this string and does not
    # carry the filter raises on its first record — so if one is ever added,
    # add the filter with it.
    formatter = logging.Formatter(
        '[%(asctime)s] %(levelname)s [%(name)s:%(lineno)d] [%(request_id)s] %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S',
    )

    # -------------------------------------------------------------------------
    # 1. Error Log Handler
    # -------------------------------------------------------------------------
    error_handler = RotatingFileHandler(
        os.path.join(log_dir, 'errors.log'),
        maxBytes=10 * 1024 * 1024,  # 10 MB
        backupCount=10,
    )
    error_handler.setLevel(logging.ERROR)
    error_handler.setFormatter(formatter)
    error_handler.addFilter(sensitive_filter)
    error_handler.addFilter(request_id_filter)
    app.logger.addHandler(error_handler)

    # -------------------------------------------------------------------------
    # 2. Authentication Log Handler
    # -------------------------------------------------------------------------
    auth_handler = RotatingFileHandler(
        os.path.join(log_dir, 'auth.log'),
        maxBytes=10 * 1024 * 1024,  # 10 MB
        backupCount=5,
    )
    auth_handler.setLevel(logging.INFO)
    auth_handler.setFormatter(formatter)
    auth_handler.addFilter(sensitive_filter)
    auth_handler.addFilter(request_id_filter)

    # Create a named logger specifically for auth events
    auth_logger = logging.getLogger('team_tryouts.auth')
    auth_logger.setLevel(logging.INFO)
    auth_logger.addHandler(auth_handler)
    auth_logger.propagate = False  # Don't double-log to root

    # -------------------------------------------------------------------------
    # 3. Application Log Handler (general)
    # -------------------------------------------------------------------------
    app_handler = RotatingFileHandler(
        os.path.join(log_dir, 'app.log'),
        maxBytes=10 * 1024 * 1024,  # 10 MB
        backupCount=10,
    )
    app_handler.setLevel(log_level)
    app_handler.setFormatter(formatter)
    app_handler.addFilter(sensitive_filter)
    app_handler.addFilter(request_id_filter)
    app.logger.addHandler(app_handler)

    # -------------------------------------------------------------------------
    # 4. Console Handler (always on)
    # -------------------------------------------------------------------------
    # Previously gated on FLASK_DEBUG, which meant production emitted nothing
    # on stdout — precisely where the Pterodactyl console looks. Keep the
    # handler unconditional and vary the level instead.
    debug_mode = os.getenv('FLASK_DEBUG', 'false').lower() == 'true'
    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.DEBUG if debug_mode else log_level)
    console_handler.setFormatter(formatter)
    console_handler.addFilter(sensitive_filter)
    console_handler.addFilter(request_id_filter)
    app.logger.addHandler(console_handler)

    # -------------------------------------------------------------------------
    # 5. Package logger ('app.*') — notably app.discord_bot
    # -------------------------------------------------------------------------
    # Modules using logging.getLogger(__name__) resolve to 'app.<module>'.
    # Without handlers here their INFO records were dropped entirely and
    # WARNING+ fell through to Python's lastResort handler, unformatted.
    package_logger = logging.getLogger('app')
    package_logger.setLevel(log_level)
    package_logger.propagate = False
    for handler in (error_handler, app_handler, console_handler):
        if handler not in package_logger.handlers:
            package_logger.addHandler(handler)

    # Log startup information
    app.logger.info('Logging configured - Level: %s, Log directory: %s', log_level_name, log_dir)
    app.logger.info('Application startup')

    return app.logger


# Module-level auth logger factory
def get_auth_logger():
    """Get the authentication event logger.

    Returns:
        logging.Logger: Logger for authentication events.
    """
    return logging.getLogger('team_tryouts.auth')


def log_auth_event(event, **fields):
    """Record a security-relevant event to auth.log.

    The handler, its rotation and its redaction filter were configured from
    the start, but get_auth_logger was never imported anywhere: auth.log was
    created and stayed empty. No login, failure, lockout, role change or
    account deletion left any trace.

    Fields are emitted as `key=value` pairs, ordered, so the file stays
    greppable without pulling in a JSON logging dependency.

    Note on `ip`: it is taken from request.remote_addr, which reflects
    X-Forwarded-For. As long as Waitress runs with trusted_proxy='*'
    (SEC-WEB-002), that value is attacker-controlled and must be read as an
    indication rather than as evidence.

    Args:
        event: Dotted event name, e.g. 'login.success'.
        **fields: Additional context. Never pass a secret: values are
            recorded verbatim apart from the redaction filter's patterns.
    """
    from flask import has_request_context, request

    parts = [f'event={event}']
    if has_request_context():
        parts.append(f'ip={request.remote_addr}')
        parts.append(f'path={request.path}')
    parts.extend(f'{key}={value}' for key, value in fields.items())

    get_auth_logger().info(' '.join(parts))