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
from logging.handlers import RotatingFileHandler
import re


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:
            # A malformed format string must not lose the record entirely.
            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.
    """
    log_dir = os.path.join(os.getcwd(), 'logs')
    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()

    # Formatter with timestamp, level, module, and message
    formatter = logging.Formatter(
        '[%(asctime)s] %(levelname)s [%(name)s:%(lineno)d] %(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)
    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)

    # 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.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)
    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 = ['event=%s' % event]
    if has_request_context():
        parts.append('ip=%s' % request.remote_addr)
        parts.append('path=%s' % request.path)
    parts.extend('%s=%s' % (key, value) for key, value in fields.items())

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