ReMe/tests/unit/test_logging_config.py

"""Tests for logging configuration handoff during app startup."""

import concurrent.futures
from datetime import datetime
import io
import logging
import threading
import time
from unittest.mock import Mock

import pytest

from reme.application import Application
from reme.config.config_parser import resolve_app_config
from reme.utils import logger_utils


class DummyLogger:
    """Minimal logger used to capture initialization without touching sinks."""

    def bind(self, **_kwargs):
        """No-op."""
        return self

    def info(self, *_args, **_kwargs):
        """No-op."""
        return None


def test_loguru_filename_includes_start_time_and_process_id(monkeypatch, tmp_path):
    """Independent ReMe processes should write to distinct Loguru files."""
    fixed_datetime = Mock()
    fixed_datetime.now.return_value = datetime(2026, 7, 20, 15, 42, 18)
    monkeypatch.setattr(logger_utils, "datetime", fixed_datetime)
    monkeypatch.setattr(logger_utils.os, "getpid", lambda: 31247)

    logger = logger_utils._init_loguru(str(tmp_path), "INFO", False, True)  # pylint: disable=protected-access
    try:
        assert (tmp_path / "2026-07-20_15-42-18_31247.log").is_file()
    finally:
        logger.remove()


def test_stdlib_formatter_matches_qwenpaw_console_format(monkeypatch, tmp_path, capsys):
    """Stdlib logs should use QwenPaw's level/path/time/message layout."""
    monkeypatch.chdir(tmp_path)
    monkeypatch.setenv("REME_DISABLE_LOGURU", "true")
    source_path = tmp_path / "src" / "qwenpaw" / "worker.py"
    record = logging.LogRecord(
        name="reme",
        level=logging.INFO,
        pathname=str(source_path),
        lineno=42,
        msg="Memory index loaded",
        args=(),
        exc_info=None,
    )
    record.created = 0

    logger = logger_utils.get_logger(log_to_file=False, force_init=True)
    logger.handle(record)

    formatted_time = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(record.created))
    assert capsys.readouterr().out == (f"INFO src/qwenpaw/worker.py:42 | {formatted_time} | Memory index loaded\n")
    logger_utils.get_logger(log_to_console=False, log_to_file=False, force_init=True)


def test_stdlib_file_creation_is_delayed_until_first_record(monkeypatch, tmp_path):
    """Stdlib logging should not leave an empty file when no records are emitted."""
    fixed_datetime = Mock()
    fixed_datetime.now.return_value = datetime(2026, 7, 23, 17, 50, 25)
    monkeypatch.setattr(logger_utils, "datetime", fixed_datetime)

    logger = logger_utils._init_stdlib(str(tmp_path), "INFO", False, True)  # pylint: disable=protected-access
    log_path = tmp_path / "2026-07-23_17-50-25.log"
    try:
        assert not log_path.exists()

        logger.info("Application started")

        assert log_path.read_text(encoding="utf-8").endswith("Application started\n")
    finally:
        for handler in list(logger.handlers):
            logger.removeHandler(handler)
            handler.close()


def test_stdlib_forwards_screen_and_file_logs_to_qwenpaw(monkeypatch, tmp_path):
    """Embedded stdlib logging should reuse QwenPaw's active sinks."""
    monkeypatch.chdir(tmp_path)
    monkeypatch.setenv("REME_DISABLE_LOGURU", "true")
    monkeypatch.setattr(logger_utils, "_logger", None)

    qwenpaw_logger = logging.getLogger("qwenpaw")
    original_handlers = list(qwenpaw_logger.handlers)
    original_level = qwenpaw_logger.level
    original_propagate = qwenpaw_logger.propagate
    for handler in original_handlers:
        qwenpaw_logger.removeHandler(handler)

    console_stream = io.StringIO()
    console_handler = logging.StreamHandler(console_stream)
    file_path = tmp_path / "qwenpaw.log"
    file_handler = logging.FileHandler(file_path, encoding="utf-8")
    formatter = logging.Formatter("%(levelname)s | %(message)s")
    console_handler.setFormatter(formatter)
    file_handler.setFormatter(formatter)
    qwenpaw_logger.addHandler(console_handler)
    qwenpaw_logger.addHandler(file_handler)
    qwenpaw_logger.setLevel(logging.INFO)
    qwenpaw_logger.propagate = False

    reme_logger = logging.getLogger("reme")
    try:
        logger = logger_utils.get_logger(
            log_to_console=True,
            log_to_file=True,
            force_init=True,
        )
        logger.info("Memory index loaded")
        file_handler.flush()

        assert console_stream.getvalue() == "INFO | Memory index loaded\n"
        assert file_path.read_text(encoding="utf-8") == "INFO | Memory index loaded\n"
        assert not (tmp_path / "logs").exists()
        assert len(reme_logger.handlers) == 1
        assert reme_logger.handlers[0].target_name == "qwenpaw"
    finally:
        for handler in list(reme_logger.handlers):
            reme_logger.removeHandler(handler)
            handler.close()
        qwenpaw_logger.removeHandler(console_handler)
        qwenpaw_logger.removeHandler(file_handler)
        console_handler.close()
        file_handler.close()
        for handler in original_handlers:
            qwenpaw_logger.addHandler(handler)
        qwenpaw_logger.setLevel(original_level)
        qwenpaw_logger.propagate = original_propagate


def test_explicit_loguru_enable_keeps_original_backend(monkeypatch):
    """An explicit false value must continue to select Loguru unchanged."""
    sentinel_logger = object()
    calls = []

    def fake_init(*args, **kwargs):
        calls.append((args, kwargs))
        return sentinel_logger

    monkeypatch.setenv("REME_DISABLE_LOGURU", "false")
    monkeypatch.setattr(logger_utils, "_logger", None)
    monkeypatch.setattr(logger_utils, "_init_loguru", fake_init)
    monkeypatch.setattr(
        logger_utils,
        "_init_stdlib",
        lambda *_args, **_kwargs: pytest.fail("stdlib backend selected"),
    )

    result = logger_utils.get_logger(force_init=True)

    assert result is sentinel_logger
    assert len(calls) == 1


def test_resolve_app_config_does_not_create_file_logger(monkeypatch):
    """Config-loading messages should not create empty run log files."""
    calls = []

    def fake_get_logger(**kwargs):
        calls.append(kwargs)
        return DummyLogger()

    monkeypatch.setattr("reme.utils.get_logger", fake_get_logger)

    resolve_app_config(config="demo")

    assert calls[0]["log_to_file"] is False


def test_application_reinitializes_logger_from_final_config(monkeypatch, tmp_path):
    """Application startup should install sinks from the resolved ApplicationConfig."""
    calls = []

    def fake_get_logger(**kwargs):
        calls.append(kwargs)
        return DummyLogger()

    monkeypatch.setattr("reme.application.get_logger", fake_get_logger)
    monkeypatch.setattr("reme.components.base_component.get_logger", lambda **_kwargs: DummyLogger())
    monkeypatch.setattr(Application, "_init_service", lambda self: setattr(self.context, "service", None))
    monkeypatch.setattr(Application, "_init_components", lambda self: None)
    monkeypatch.setattr(Application, "_init_jobs", lambda self: None)

    Application(
        enable_logo=False,
        log_to_console=False,
        log_to_file=True,
        workspace_dir=str(tmp_path / "workspace"),
        service={"backend": "unused"},
    )

    assert calls[0] == {
        "log_to_console": False,
        "log_to_file": True,
        "force_init": True,
    }


@pytest.mark.parametrize("use_loguru", [True, False])
def test_concurrent_force_init_is_serialized(monkeypatch, use_loguru):
    """Concurrent application startup must not overlap global logger resets."""
    state_lock = threading.Lock()
    active_initializers = 0
    max_active_initializers = 0
    initialization_count = 0
    sentinel_logger = object()

    def fake_init(*_args, **_kwargs):
        nonlocal active_initializers
        nonlocal max_active_initializers
        nonlocal initialization_count

        with state_lock:
            active_initializers += 1
            initialization_count += 1
            max_active_initializers = max(
                max_active_initializers,
                active_initializers,
            )
        time.sleep(0.01)
        with state_lock:
            active_initializers -= 1
        return sentinel_logger

    monkeypatch.setattr(logger_utils, "_logger", None)
    monkeypatch.setattr(logger_utils, "_enable_loguru", lambda: use_loguru)
    monkeypatch.setattr(logger_utils, "_init_loguru", fake_init)
    monkeypatch.setattr(logger_utils, "_init_stdlib", fake_init)

    with concurrent.futures.ThreadPoolExecutor(max_workers=16) as pool:
        results = list(
            pool.map(
                lambda _index: logger_utils.get_logger(force_init=True),
                range(32),
            ),
        )

    assert results == [sentinel_logger] * 32
    assert initialization_count == 32
    assert max_active_initializers == 1