Corp/backend/tests/test_logging.py

from __future__ import annotations

import ast
import json
import logging
import re
from pathlib import Path
from types import SimpleNamespace

import pytest
from billiard.einfo import ExceptionInfo
from billiard.exceptions import WorkerLostError
from django.conf import settings
from django.http import HttpResponse
from django.test import RequestFactory
from django.test.utils import override_settings

from api.auth.authentication import SessionAwareJWTAuthentication
from eusrr_backend.auth_backends import EmailOrPhoneBackend
from eusrr_backend.celery import (
    _normalize_failure_traceback,
    inject_task_log_context,
    log_task_completed,
    log_task_failed,
    log_task_started,
)
from eusrr_backend.channels_jwt import JWTAuthMiddleware
from eusrr_backend.logging_utils import (
    ConsoleFormatter,
    ContextFilter,
    JsonFormatter,
    WebSocketLoggingMiddleware,
    bind_log_context,
    get_log_context,
    reset_log_context,
)
from eusrr_backend.middleware import RequestLoggingMiddleware

BACKEND_ROOT = Path(__file__).resolve().parents[1]


def _record(message="operation completed", **extra):
    record = logging.LogRecord(
        "test.logging",
        logging.INFO,
        __file__,
        10,
        message,
        (),
        None,
    )
    for key, value in extra.items():
        setattr(record, key, value)
    return record


def test_json_formatter_emits_context_and_structured_fields():
    token = bind_log_context(request_id="req-123", user_id=42)
    try:
        output = JsonFormatter().format(
            _record(
                event="document.created",
                document_id=7,
                duration_ms=12.5,
            )
        )
    finally:
        reset_log_context(token)

    payload = json.loads(output)
    assert payload["event"] == "document.created"
    assert payload["request_id"] == "req-123"
    assert payload["user_id"] == 42
    assert payload["document_id"] == 7
    assert payload["duration_ms"] == 12.5
    assert payload["source"].endswith(":10")


def test_logging_settings_use_one_context_aware_console_pipeline():
    config = settings.LOGGING

    assert config["root"]["handlers"] == ["console"]
    assert config["handlers"]["console"]["filters"] == ["context"]
    assert config["handlers"]["console"]["formatter"] in {"console", "json"}
    assert "eusrr_backend.auth_backends" not in config["loggers"]
    assert settings.CELERY_WORKER_HIJACK_ROOT_LOGGER is False
    assert isinstance(settings.LOG_TRUST_X_FORWARDED_FOR, bool)
    assert config["loggers"]["daphne"]["level"] == "WARNING"
    assert config["loggers"]["daphne"]["propagate"] is False
    assert config["loggers"]["django.channels.server"]["level"] == "WARNING"
    assert config["loggers"]["django.channels.server"]["propagate"] is False
    assert config["loggers"]["httpcore"]["level"] == "WARNING"
    assert config["loggers"]["httpcore"]["propagate"] is False
    assert config["loggers"]["httpx"]["level"] == "WARNING"
    assert config["loggers"]["httpx"]["propagate"] is False


def test_context_filter_assigns_stable_event_to_framework_logs():
    record = _record("transport warning")
    record.name = "daphne.ws_protocol"
    record.levelno = logging.WARNING
    record.levelname = "WARNING"

    assert ContextFilter().filter(record) is True
    assert record.event == "framework.daphne_ws_protocol.warning"


def test_formatter_removes_terminal_ansi_sequences():
    record = _record("\x1b[mHTTP GET /health/ 200\x1b[0m", event="server.access")

    output = ConsoleFormatter().format(record)

    assert "\\u001b" not in output
    assert "\x1b" not in output
    assert "HTTP GET /health/ 200" in output


def test_console_formatter_groups_http_context_and_event_data():
    output = ConsoleFormatter().format(
        _record(
            "HTTP request completed",
            event="http.request.completed",
            http_method="GET",
            path="/api/v1/tasks/boards/1/",
            status_code=200,
            duration_ms=27.5,
            request_id="req-123",
            user_id=42,
            client_ip="127.0.0.1",
            cache_hit=True,
        )
    )

    assert "INFO [HTTP] http.request.completed @test.logging" in output
    assert '[GET "/api/v1/tasks/boards/1/" → 200 27.5ms]' in output
    assert '[req="req-123" user=42 ip="127.0.0.1"]' in output
    assert "[cache_hit=true]" in output
    assert '"HTTP request completed"' in output
    assert "level=" not in output
    assert "logger=" not in output
    assert "event=" not in output
    assert "status_code=" not in output
    assert "duration_ms=" not in output
    assert "message=" not in output
    assert "\x1b" not in output
    assert output.index("[GET ") < output.index("[req=")
    assert output.index("[req=") < output.index("[cache_hit=")


def test_console_formatter_does_not_repeat_websocket_correlation_id():
    connection_id = "connection-123"
    output = ConsoleFormatter().format(
        _record(
            "WebSocket connection accepted",
            event="websocket.connection.accepted",
            connection_id=connection_id,
            request_id=connection_id,
            path="/ws/",
            user_id=42,
        )
    )

    assert output.count(connection_id) == 1
    assert '[conn="connection-123" path="/ws/"]' in output
    assert "[user=42]" in output


@pytest.mark.parametrize("formatter", [ConsoleFormatter(), JsonFormatter()])
def test_formatters_redact_secrets_and_escape_newlines(formatter):
    output = formatter.format(
        _record(
            "token=top-secret Authorization: Bearer jwt-value\nsecond line",
            event="security.test",
            password="plain-password",
            cookie="session=abc",
        )
    )

    assert "top-secret" not in output
    assert "jwt-value" not in output
    assert "plain-password" not in output
    assert "session=abc" not in output
    assert "\nsecond line" not in output
    assert "\\nsecond line" in output


@pytest.mark.parametrize("formatter", [ConsoleFormatter(), JsonFormatter()])
def test_formatters_redact_personal_directory_data_and_bound_values(formatter):
    output = formatter.format(
        _record(
            "employee=CN=Private Person,OU=Users,DC=example,DC=test "
            "phone=+7 (999) 123-45-67 " + "x" * 3000,
            event="security.directory_data",
        )
    )

    assert "Private Person" not in output
    assert "999" not in output
    assert "[REDACTED_DN]" in output
    assert "[REDACTED_PHONE]" in output
    assert "[TRUNCATED]" in output


def test_formatter_serializes_exception_without_losing_event():
    try:
        raise ValueError("broken")
    except ValueError:
        record = _record(event="operation.failed")
        record.exc_info = __import__("sys").exc_info()

    payload = json.loads(JsonFormatter().format(record))
    assert payload["event"] == "operation.failed"
    assert "ValueError" in payload["exception"]


def test_worker_lost_string_traceback_does_not_break_celery_logging(monkeypatch):
    captured = {}

    def capture_error(message, **kwargs):
        captured.update(message=message, **kwargs)

    monkeypatch.setattr("eusrr_backend.celery.logger.error", capture_error)
    failure = WorkerLostError("worker exited with SIGTERM")

    log_task_failed(
        sender=SimpleNamespace(name="commerce.sync_connection_run"),
        task_id="lost-task",
        exception=failure,
        traceback="serialized billiard traceback",
    )

    assert captured["exc_info"] is None
    assert captured["extra"]["failure_traceback"] == ("serialized billiard traceback")
    record = _record(**captured["extra"])
    record.exc_info = captured["exc_info"]
    assert "WorkerLostError" in JsonFormatter().format(record)


def test_billiard_exception_info_is_normalized_to_real_traceback():
    try:
        raise RuntimeError("original worker failure")
    except RuntimeError as error:
        billiard_info = ExceptionInfo()
        exc_info, fallback = _normalize_failure_traceback(error, billiard_info)

    assert exc_info is not None
    assert exc_info[2].tb_frame is not None
    assert fallback
    record = _record(event="celery.task.failed")
    record.exc_info = exc_info
    payload = json.loads(JsonFormatter().format(record))
    assert "original worker failure" in payload["exception"]


@pytest.mark.parametrize("formatter", [ConsoleFormatter(), JsonFormatter()])
def test_formatter_survives_malformed_string_exc_info(formatter):
    failure = WorkerLostError("worker disappeared")
    record = _record(event="celery.task.failed")
    record.exc_info = (WorkerLostError, failure, "not-a-traceback-object")

    output = formatter.format(record)

    assert "worker disappeared" in output


def test_formatter_sanitizes_django_request_extra():
    request = RequestFactory().get(
        "/api/v1/documents/?token=query-secret&search=private"
    )
    record = _record(event="django.request.failed")
    record.request = request

    payload = json.loads(JsonFormatter().format(record))

    assert payload["request"] == {
        "method": "GET",
        "path": "/api/v1/documents/",
    }
    assert "query-secret" not in json.dumps(payload)
    assert "private" not in json.dumps(payload)


def test_http_middleware_accepts_safe_request_id_and_cleans_context(monkeypatch):
    contexts = []
    log_calls = []

    def get_response(request):
        contexts.append(get_log_context())
        return HttpResponse("ok", status=200)

    monkeypatch.setattr(
        "eusrr_backend.middleware.logger.info",
        lambda message, **kwargs: log_calls.append((message, kwargs)),
    )
    request = RequestFactory().get(
        "/api/v1/documents/?token=must-not-leak",
        HTTP_X_REQUEST_ID="trace-123",
        REMOTE_ADDR="127.0.0.7",
    )
    request.user = SimpleNamespace(is_authenticated=True, pk=42)

    response = RequestLoggingMiddleware(get_response)(request)

    assert response["X-Request-ID"] == "trace-123"
    assert contexts == [
        {
            "request_id": "trace-123",
            "user_id": 42,
            "http_method": "GET",
            "path": "/api/v1/documents/",
            "client_ip": "127.0.0.7",
        }
    ]
    assert get_log_context() == {}
    assert log_calls[0][1]["extra"]["event"] == "http.request.completed"
    assert log_calls[0][1]["extra"]["status_code"] == 200


def test_http_middleware_replaces_unsafe_request_id():
    request = RequestFactory().get(
        "/health/", HTTP_X_REQUEST_ID="bad id\nAuthorization: secret"
    )
    request.user = SimpleNamespace(is_authenticated=False)

    response = RequestLoggingMiddleware(lambda request: HttpResponse("ok"))(request)

    assert response["X-Request-ID"] != request.headers["X-Request-ID"]
    assert len(response["X-Request-ID"]) == 32
    assert get_log_context() == {}


@override_settings(LOG_TRUST_X_FORWARDED_FOR=True)
def test_http_middleware_uses_valid_trusted_proxy_ip():
    contexts = []
    request = RequestFactory().get(
        "/health/",
        HTTP_X_FORWARDED_FOR="203.0.113.10, 10.0.0.5",
        REMOTE_ADDR="10.0.0.5",
    )
    request.user = SimpleNamespace(is_authenticated=False)

    RequestLoggingMiddleware(
        lambda request: contexts.append(get_log_context()) or HttpResponse("ok")
    )(request)

    assert contexts[0]["client_ip"] == "203.0.113.10"
    assert get_log_context() == {}


@override_settings(LOG_TRUST_X_FORWARDED_FOR=True)
def test_http_middleware_rejects_invalid_forwarded_ip():
    contexts = []
    request = RequestFactory().get(
        "/health/",
        HTTP_X_FORWARDED_FOR="attacker-controlled-value",
        REMOTE_ADDR="192.0.2.20",
    )
    request.user = SimpleNamespace(is_authenticated=False)

    RequestLoggingMiddleware(
        lambda request: contexts.append(get_log_context()) or HttpResponse("ok")
    )(request)

    assert contexts[0]["client_ip"] == "192.0.2.20"


def test_http_jwt_authentication_binds_user_before_view_logging(monkeypatch):
    user = SimpleNamespace(pk=73)
    validated_token = object()
    monkeypatch.setattr(
        "rest_framework_simplejwt.authentication.JWTAuthentication.authenticate",
        lambda authentication, request: (user, validated_token),
    )
    monkeypatch.setattr(
        SessionAwareJWTAuthentication,
        "validate_session",
        lambda authentication, token, user, request=None: None,
    )
    token = bind_log_context(client_ip="203.0.113.11")
    try:
        result = SessionAwareJWTAuthentication().authenticate(SimpleNamespace())
        assert result == (user, validated_token)
        assert get_log_context() == {
            "client_ip": "203.0.113.11",
            "user_id": 73,
        }
    finally:
        reset_log_context(token)


@pytest.mark.asyncio
async def test_websocket_middleware_logs_lifecycle_without_query_string(caplog):
    sent = []

    async def app(scope, receive, send):
        assert get_log_context()["path"] == "/ws/notifications/"
        assert "query_string" not in get_log_context()
        await send({"type": "websocket.accept"})
        await receive()

    messages = iter([{"type": "websocket.disconnect", "code": 1000}])

    async def receive():
        return next(messages)

    async def send(message):
        sent.append(message)

    scope = {
        "type": "websocket",
        "path": "/ws/notifications/",
        "query_string": b"token=must-not-leak",
        "headers": [(b"x-request-id", b"ws-123")],
        "client": ("127.0.0.8", 10000),
    }
    with caplog.at_level(logging.INFO, logger="eusrr.websocket"):
        await WebSocketLoggingMiddleware(app)(scope, receive, send)

    assert scope["request_id"] == "ws-123"
    assert [record.event for record in caplog.records] == [
        "websocket.connection.accepted",
        "websocket.connection.closed",
    ]
    assert caplog.records[-1].close_code == 1000
    assert get_log_context() == {}


@pytest.mark.asyncio
@override_settings(LOG_TRUST_X_FORWARDED_FOR=True)
async def test_websocket_middleware_uses_valid_trusted_proxy_ip():
    async def app(scope, receive, send):
        assert get_log_context()["client_ip"] == "2001:db8::7"

    scope = {
        "type": "websocket",
        "path": "/ws/notifications/",
        "headers": [(b"x-forwarded-for", b"2001:db8::7, 10.0.0.5")],
        "client": ("10.0.0.5", 10000),
    }

    await WebSocketLoggingMiddleware(app)(scope, None, None)
    assert get_log_context() == {}


@pytest.mark.asyncio
async def test_websocket_session_authentication_binds_user_context():
    async def app(scope, receive, send):
        assert get_log_context()["user_id"] == 91

    token = bind_log_context(client_ip="203.0.113.12")
    try:
        await JWTAuthMiddleware(app)(
            {
                "type": "websocket",
                "headers": [],
                "query_string": b"",
                "user": SimpleNamespace(is_authenticated=True, pk=91),
            },
            None,
            None,
        )
    finally:
        reset_log_context(token)


def test_celery_lifecycle_has_task_context_and_duration(caplog):
    sender = SimpleNamespace(name="documents.tasks.index")

    with caplog.at_level(logging.INFO, logger="eusrr.celery"):
        log_task_started(sender=sender, task_id="task-123")
        log_task_completed(
            sender=sender,
            task_id="task-123",
            state="SUCCESS",
        )

    assert [record.event for record in caplog.records] == [
        "celery.task.started",
        "celery.task.completed",
    ]
    assert caplog.records[0].task_id == "task-123"
    assert caplog.records[-1].task_name == "documents.tasks.index"
    assert caplog.records[-1].duration_ms >= 0
    assert get_log_context() == {}


def test_celery_propagates_safe_request_context_through_headers():
    headers = {}
    token = bind_log_context(
        request_id="request-123",
        user_id=42,
        client_ip="203.0.113.15",
        path="/must-not-propagate/",
    )
    try:
        inject_task_log_context(headers=headers)
    finally:
        reset_log_context(token)

    assert headers == {
        "eusrr_log_context": {
            "request_id": "request-123",
            "user_id": 42,
            "client_ip": "203.0.113.15",
        }
    }

    sender = SimpleNamespace(
        name="notifications.tasks.send",
        request=SimpleNamespace(headers=headers),
    )
    log_task_started(sender=sender, task_id="task-context-1")
    assert get_log_context() == {
        "request_id": "request-123",
        "user_id": 42,
        "client_ip": "203.0.113.15",
        "task_id": "task-context-1",
        "task_name": "notifications.tasks.send",
    }
    log_task_completed(sender=sender, task_id="task-context-1", state="SUCCESS")
    assert get_log_context() == {}


def test_celery_derives_user_id_from_named_positional_task_argument():
    def run(user_id, frequency="daily"):
        return None

    sender = SimpleNamespace(
        name="notifications.send_digest",
        request=SimpleNamespace(headers={}),
        run=run,
    )
    log_task_started(
        sender=sender,
        task_id="task-context-2",
        args=(84,),
        kwargs={"frequency": "weekly"},
    )
    assert get_log_context()["user_id"] == 84
    log_task_completed(sender=sender, task_id="task-context-2", state="SUCCESS")
    assert get_log_context() == {}


@pytest.mark.django_db
def test_failed_authentication_does_not_log_identifier_password_or_hash(
    caplog, user_factory
):
    user = user_factory(email="private-person@example.test")
    password_hash = user.password

    with caplog.at_level(logging.WARNING, logger="eusrr_backend.auth_backends"):
        result = EmailOrPhoneBackend().authenticate(
            None,
            username=user.email,
            password="plain-secret-password",
        )

    assert result is None
    output = JsonFormatter().format(caplog.records[-1])
    assert caplog.records[-1].event == "authentication.local.denied"
    assert caplog.records[-1].reason == "invalid_password"
    assert "private-person@example.test" not in output
    assert "plain-secret-password" not in output
    assert password_hash not in output


def test_production_python_does_not_use_print_for_runtime_logging():
    excluded_parts = {".venv", "docs", "migrations", "scripts", "tests"}
    violations = []

    for path in BACKEND_ROOT.rglob("*.py"):
        if any(part in excluded_parts for part in path.parts):
            continue
        tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path))
        for node in ast.walk(tree):
            if (
                isinstance(node, ast.Call)
                and isinstance(node.func, ast.Name)
                and node.func.id == "print"
            ):
                violations.append(f"{path.relative_to(BACKEND_ROOT)}:{node.lineno}")

    assert violations == []


def test_structured_log_extras_do_not_overwrite_log_record_fields():
    excluded_parts = {".venv", "docs", "migrations", "scripts", "tests"}
    reserved = set(logging.makeLogRecord({}).__dict__) | {"message", "asctime"}
    violations = []

    for path in BACKEND_ROOT.rglob("*.py"):
        if any(part in excluded_parts for part in path.parts):
            continue
        tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path))
        for node in ast.walk(tree):
            if not (
                isinstance(node, ast.Call)
                and isinstance(node.func, ast.Attribute)
                and node.func.attr
                in {"debug", "info", "warning", "error", "exception", "critical", "log"}
            ):
                continue
            for keyword in node.keywords:
                if keyword.arg != "extra" or not isinstance(keyword.value, ast.Dict):
                    continue
                for key in keyword.value.keys:
                    if isinstance(key, ast.Constant) and key.value in reserved:
                        violations.append(
                            f"{path.relative_to(BACKEND_ROOT)}:{node.lineno}:{key.value}"
                        )

    assert violations == []


def test_production_logger_calls_have_explicit_well_formed_events():
    excluded_parts = {".venv", "docs", "migrations", "scripts", "tests"}
    levels = {"debug", "info", "warning", "error", "exception", "critical", "log"}
    event_pattern = re.compile(r"[a-z][a-z0-9_]*(?:\.[a-z0-9_]+)+")
    violations = []
    logger_call_count = 0

    for path in BACKEND_ROOT.rglob("*.py"):
        if any(part in excluded_parts for part in path.parts):
            continue
        tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path))
        for node in ast.walk(tree):
            if not (
                isinstance(node, ast.Call)
                and isinstance(node.func, ast.Attribute)
                and node.func.attr in levels
            ):
                continue
            receiver = node.func.value
            receiver_name = (
                receiver.id
                if isinstance(receiver, ast.Name)
                else receiver.attr
                if isinstance(receiver, ast.Attribute)
                else ""
            )
            if receiver_name != "logger" and not receiver_name.endswith("_logger"):
                continue

            logger_call_count += 1
            event_value = None
            for keyword in node.keywords:
                if keyword.arg != "extra" or not isinstance(keyword.value, ast.Dict):
                    continue
                for key, value in zip(keyword.value.keys, keyword.value.values):
                    if isinstance(key, ast.Constant) and key.value == "event":
                        event_value = value
                        break

            if event_value is None:
                violations.append(
                    f"{path.relative_to(BACKEND_ROOT)}:{node.lineno}:missing"
                )
            elif isinstance(event_value, ast.Constant):
                if not isinstance(
                    event_value.value, str
                ) or not event_pattern.fullmatch(event_value.value):
                    violations.append(
                        f"{path.relative_to(BACKEND_ROOT)}:{node.lineno}:invalid"
                    )
            elif not (isinstance(event_value, ast.Name) and event_value.id == "event"):
                violations.append(
                    f"{path.relative_to(BACKEND_ROOT)}:{node.lineno}:dynamic"
                )

    assert logger_call_count >= 400
    assert violations == []