stack/tests/bcda/test_log.py

"""Tests for bcda.log — JSONL structured logging."""

from __future__ import annotations

import json
import logging

import pytest

from bcda.log import JsonlHandler, setup


@pytest.fixture()
def log_path(tmp_path):
    return tmp_path / "test.jsonl"


class TestJsonlHandler:
    def test_creates_parent_dirs(self, tmp_path) -> None:
        path = tmp_path / "nested" / "dir" / "log.jsonl"
        handler = JsonlHandler(path)
        assert path.parent.exists()
        handler.close()

    def test_writes_json_line(self, log_path) -> None:
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.jsonl")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info("hello world")
        handler.close()

        lines = log_path.read_text().strip().split("\n")
        assert len(lines) == 1
        entry = json.loads(lines[0])
        assert entry["message"] == "hello world"
        assert entry["level"] == "INFO"
        assert entry["logger"] == "test.bcda.jsonl"
        assert "ts" in entry
        logger.removeHandler(handler)

    def test_multiple_records(self, log_path) -> None:
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.multi")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info("first")
        logger.warning("second")
        logger.debug("third")
        handler.close()

        lines = log_path.read_text().strip().split("\n")
        assert len(lines) == 3
        levels = [json.loads(line)["level"] for line in lines]
        assert levels == ["INFO", "WARNING", "DEBUG"]
        logger.removeHandler(handler)

    def test_custom_attrs(self, log_path) -> None:
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.custom")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info(
            "with extra",
            extra={"job_id": "abc123", "count": 42},
        )
        handler.close()

        entry = json.loads(log_path.read_text().strip())
        assert entry["job_id"] == "abc123"
        assert entry["count"] == 42
        logger.removeHandler(handler)

    def test_exception_info(self, log_path) -> None:
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.exc")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        try:
            raise ValueError("test error")
        except ValueError:
            logger.exception("caught error")
        handler.close()

        entry = json.loads(log_path.read_text().strip())
        assert entry["message"] == "caught error"
        assert "exception" in entry
        assert any("ValueError" in line for line in entry["exception"])
        logger.removeHandler(handler)

    def test_append_mode(self, log_path) -> None:
        log_path.write_text('{"existing": true}\n')
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.append")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info("appended")
        handler.close()

        lines = log_path.read_text().strip().split("\n")
        assert len(lines) == 2
        logger.removeHandler(handler)

    def test_non_serializable_extra(self, log_path) -> None:
        """Non-JSON-serializable extras are repr'd."""
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.nonser")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info("test", extra={"obj": object()})
        handler.close()

        entry = json.loads(log_path.read_text().strip())
        assert "object" in entry["obj"].lower()
        logger.removeHandler(handler)

    def test_private_keys_excluded(self, log_path) -> None:
        """Keys starting with _ are excluded."""
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.private")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        logger.info("test", extra={"_private": "skip", "public": "keep"})
        handler.close()

        entry = json.loads(log_path.read_text().strip())
        assert "_private" not in entry
        assert entry["public"] == "keep"
        logger.removeHandler(handler)

    def test_extra_collides_with_builtin_key(self, log_path) -> None:
        """Extra key that collides with entry key (ts/level/etc) is skipped."""
        handler = JsonlHandler(log_path)
        logger = logging.getLogger("test.bcda.collide")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        # "ts" and "level" are already set in the entry dict.
        logger.info(
            "test",
            extra={"ts": "conflict", "level": "BAD"},
        )
        handler.close()

        entry = json.loads(log_path.read_text().strip())
        # The built-in entry values should be preserved.
        assert entry["level"] == "INFO"  # NOT "BAD"
        assert "T" in entry["ts"]  # ISO timestamp, not "conflict"
        logger.removeHandler(handler)

    def test_emit_error_calls_handle_error(self, log_path) -> None:
        """When emit fails, handleError is called."""
        handler = JsonlHandler(log_path)
        # Close the file so writes fail.
        handler._file.close()

        logger = logging.getLogger("test.bcda.emit_err")
        logger.addHandler(handler)
        logger.setLevel(logging.DEBUG)
        # This should trigger the except block in emit().
        # handleError swallows the error silently by default.
        logger.info("this will fail")
        logger.removeHandler(handler)
        handler.close()

    def test_close_idempotent(self, log_path) -> None:
        """close() can be called multiple times safely."""
        handler = JsonlHandler(log_path)
        handler.close()
        handler.close()  # Should not raise.


class TestSetup:
    def test_returns_logger(self, log_path) -> None:
        logger = setup(log_path)
        assert isinstance(logger, logging.Logger)
        assert logger.name == "bcda"
        for h in logger.handlers[:]:
            if isinstance(h, JsonlHandler):
                h.close()
                logger.removeHandler(h)

    def test_sets_level(self, log_path) -> None:
        logger = setup(log_path, level=logging.WARNING)
        assert logger.level <= logging.WARNING
        for h in logger.handlers[:]:
            if isinstance(h, JsonlHandler):
                h.close()
                logger.removeHandler(h)

    def test_idempotent_same_path(self, log_path) -> None:
        logger1 = setup(log_path)
        count_before = sum(1 for h in logger1.handlers if isinstance(h, JsonlHandler))
        logger2 = setup(log_path)
        count_after = sum(1 for h in logger2.handlers if isinstance(h, JsonlHandler))
        assert count_before == count_after
        assert logger1 is logger2
        for h in logger1.handlers[:]:
            if isinstance(h, JsonlHandler):
                h.close()
                logger1.removeHandler(h)

    def test_different_paths_add_handlers(self, tmp_path) -> None:
        p1 = tmp_path / "a.jsonl"
        p2 = tmp_path / "b.jsonl"
        logger = setup(p1)
        before = sum(1 for h in logger.handlers if isinstance(h, JsonlHandler))
        setup(p2)
        after = sum(1 for h in logger.handlers if isinstance(h, JsonlHandler))
        assert after == before + 1
        for h in logger.handlers[:]:
            if isinstance(h, JsonlHandler):
                h.close()
                logger.removeHandler(h)

    def test_raises_logger_level_if_needed(self, tmp_path) -> None:
        """If logger level is higher than requested, lower it."""
        logger = logging.getLogger("bcda")
        logger.setLevel(logging.CRITICAL)
        p = tmp_path / "level.jsonl"
        setup(p, level=logging.INFO)
        assert logger.level <= logging.INFO
        for h in logger.handlers[:]:
            if isinstance(h, JsonlHandler):
                h.close()
                logger.removeHandler(h)