learningcircuit--local-deep-research/tests/utilities/test_log_utils_deep_coverage.py

"""
Tests for uncovered code paths in log_utils.py.

Targets:
- _get_research_id: record with extra, record without extra, no app context
- _process_log_queue: no app context (requeue), queue full, empty queue
- database_sink: background thread queueing, main thread direct write
- frontend_progress_sink: no research_id skips
- flush_log_queue: flushes entries, handles exceptions
- config_logger: MILESTONE level already exists, file logging, debug mode
- InterceptHandler: level not found fallback
"""

import queue
from unittest.mock import Mock, patch


MODULE = "local_deep_research.utilities.log_utils"


class TestGetResearchId:
    """Tests for _get_research_id."""

    def test_from_record_extra(self):
        """Extracts research_id from record extra."""
        from local_deep_research.utilities.log_utils import _get_research_id

        record = {"extra": {"research_id": "test-123"}}
        with patch(f"{MODULE}.has_app_context", return_value=False):
            result = _get_research_id(record)
        assert result == "test-123"

    def test_record_without_extra_uses_flask_g(self, app):
        """Falls back to Flask g when record has no extra."""
        from local_deep_research.utilities.log_utils import _get_research_id
        from flask import g

        record = {"level": "INFO"}
        with app.test_request_context():
            g.research_id = "flask-456"
            result = _get_research_id(record)
        assert result == "flask-456"

    def test_none_record_uses_flask_g(self, app):
        """None record falls back to Flask g."""
        from local_deep_research.utilities.log_utils import _get_research_id
        from flask import g

        with app.test_request_context():
            g.research_id = "g-789"
            result = _get_research_id(None)
        assert result == "g-789"

    def test_no_app_context_no_record(self):
        """Returns None when no app context and no record."""
        from local_deep_research.utilities.log_utils import _get_research_id

        with patch(f"{MODULE}.has_app_context", return_value=False):
            result = _get_research_id(None)
        assert result is None

    def test_record_with_extra_but_no_research_id(self):
        """Record with extra but no research_id falls back to Flask g."""
        from local_deep_research.utilities.log_utils import _get_research_id

        record = {"extra": {"username": "bob"}}
        with patch(f"{MODULE}.has_app_context", return_value=False):
            result = _get_research_id(record)
        assert result is None


class TestProcessLogQueue:
    """Tests for _process_log_queue."""

    def test_processes_entry_with_app_context(self):
        """Processes log entry when app context is available."""
        from local_deep_research.utilities.log_utils import (
            _process_log_queue,
            _log_queue,
            _stop_queue,
        )

        entry = {"message": "test", "research_id": "123"}
        _log_queue.put(entry)

        # Set stop flag after one iteration
        def stop_after_one(*args, **kwargs):
            _stop_queue.set()

        with patch(f"{MODULE}.has_app_context", return_value=True):
            with patch(
                f"{MODULE}._write_log_to_database", side_effect=stop_after_one
            ) as mock_write:
                _stop_queue.clear()
                _process_log_queue()
                mock_write.assert_called_once_with(entry)

        _stop_queue.clear()

    def test_requeues_without_app_context(self):
        """Puts entry back when no app context."""
        from local_deep_research.utilities.log_utils import (
            _process_log_queue,
            _log_queue,
            _stop_queue,
        )

        # Clear queue
        while not _log_queue.empty():
            try:
                _log_queue.get_nowait()
            except queue.Empty:
                break

        entry = {"message": "test", "research_id": "123"}
        _log_queue.put(entry)

        call_count = [0]

        def count_and_stop(*args, **kwargs):
            call_count[0] += 1
            if call_count[0] >= 2:
                _stop_queue.set()
            return False

        with patch(f"{MODULE}.has_app_context", side_effect=count_and_stop):
            _stop_queue.clear()
            _process_log_queue()

        _stop_queue.clear()
        # Entry should still be in queue (requeued)
        assert not _log_queue.empty()
        # Clean up
        while not _log_queue.empty():
            try:
                _log_queue.get_nowait()
            except queue.Empty:
                break

    def test_skips_none_entry(self):
        """Skips None entries."""
        from local_deep_research.utilities.log_utils import (
            _process_log_queue,
            _log_queue,
            _stop_queue,
        )

        _log_queue.put(None)
        _stop_queue.clear()

        call_count = [0]

        def mock_get(timeout=None):
            call_count[0] += 1
            if call_count[0] == 1:
                return
            _stop_queue.set()
            raise queue.Empty()

        with patch.object(_log_queue, "get", side_effect=mock_get):
            _process_log_queue()

        _stop_queue.clear()


class TestDatabaseSink:
    """Tests for database_sink."""

    def test_background_thread_queues(self):
        """Queues log entry from background thread.

        Logs need research context to be queued — ResearchLog is
        research-scoped, system logs are skipped at the boundary."""
        from local_deep_research.utilities.log_utils import (
            database_sink,
            _log_queue,
        )

        # Clear queue
        while not _log_queue.empty():
            try:
                _log_queue.get_nowait()
            except queue.Empty:
                break

        msg = Mock()
        msg.record = {
            "time": "2024-01-01",
            "message": "test",
            "name": "module",
            "function": "func",
            "line": 42,
            "level": Mock(name="INFO"),
            "extra": {"research_id": "rid-1"},
        }

        with patch(f"{MODULE}.has_app_context", return_value=False):
            database_sink(msg)

        # Entry should be in queue
        assert not _log_queue.empty()
        entry = _log_queue.get_nowait()
        assert entry["message"] == "test"
        assert entry["line_no"] == 42

    def test_main_thread_writes_directly(self, app):
        """Writes directly from main thread with app context."""
        from local_deep_research.utilities.log_utils import database_sink

        msg = Mock()
        msg.record = {
            "time": "2024-01-01",
            "message": "test",
            "name": "module",
            "function": "func",
            "line": 42,
            "level": Mock(name="INFO"),
            "extra": {"username": "bob"},
        }

        with app.test_request_context():
            with patch(f"{MODULE}.threading.current_thread") as mock_thread:
                mock_thread.return_value.name = "MainThread"
                with patch(f"{MODULE}._write_log_to_database") as mock_write:
                    database_sink(msg)
                    mock_write.assert_called_once()

    def test_queue_full_drops_silently(self):
        """Drops log when queue is full."""
        from local_deep_research.utilities.log_utils import database_sink

        msg = Mock()
        msg.record = {
            "time": "2024-01-01",
            "message": "test",
            "name": "module",
            "function": "func",
            "line": 1,
            "level": Mock(name="DEBUG"),
            "extra": {},
        }

        with patch(f"{MODULE}.has_app_context", return_value=False):
            with patch(f"{MODULE}._log_queue") as mock_queue:
                mock_queue.put_nowait.side_effect = queue.Full()
                # Should not raise
                database_sink(msg)


class TestFrontendProgressSink:
    """Tests for frontend_progress_sink."""

    def test_no_research_id_returns_early(self):
        """Returns early when no research_id."""
        from local_deep_research.utilities.log_utils import (
            frontend_progress_sink,
        )

        msg = Mock()
        msg.record = {
            "message": "test",
            "level": Mock(name="INFO"),
            "time": Mock(isoformat=Mock(return_value="2024-01-01T00:00:00")),
            "extra": {},
        }

        with patch(f"{MODULE}._get_research_id", return_value=None):
            with patch(f"{MODULE}.SocketIOService") as mock_sio:
                frontend_progress_sink(msg)
                mock_sio.assert_not_called()

    def test_with_research_id_emits(self):
        """Emits to subscribers when research_id exists."""
        from local_deep_research.utilities.log_utils import (
            frontend_progress_sink,
        )

        msg = Mock()
        msg.record = {
            "message": "Progress update",
            "level": Mock(name="INFO"),
            "time": Mock(isoformat=Mock(return_value="2024-01-01T00:00:00")),
            "extra": {"research_id": "r-123"},
        }

        with patch(f"{MODULE}._get_research_id", return_value="r-123"):
            with patch(f"{MODULE}.SocketIOService") as mock_sio_cls:
                mock_sio = Mock()
                mock_sio_cls.return_value = mock_sio

                frontend_progress_sink(msg)

                mock_sio.emit_to_subscribers.assert_called_once()
                call_args = mock_sio.emit_to_subscribers.call_args
                assert call_args[0][0] == "progress"
                assert call_args[0][1] == "r-123"


class TestFlushLogQueue:
    """Tests for flush_log_queue."""

    def test_flushes_entries(self):
        """Flushes all entries from queue to database."""
        from local_deep_research.utilities.log_utils import (
            flush_log_queue,
            _log_queue,
        )

        # Clear queue
        while not _log_queue.empty():
            try:
                _log_queue.get_nowait()
            except queue.Empty:
                break

        _log_queue.put({"message": "entry1"})
        _log_queue.put({"message": "entry2"})

        with patch(f"{MODULE}._write_log_to_database") as mock_write:
            flush_log_queue()
            assert mock_write.call_count == 2

    def test_empty_queue(self):
        """Handles empty queue gracefully."""
        from local_deep_research.utilities.log_utils import (
            flush_log_queue,
            _log_queue,
        )

        # Clear queue
        while not _log_queue.empty():
            try:
                _log_queue.get_nowait()
            except queue.Empty:
                break

        with patch(f"{MODULE}._write_log_to_database") as mock_write:
            flush_log_queue()
            mock_write.assert_not_called()


class TestInterceptHandler:
    """Tests for InterceptHandler."""

    def _make_log_record(self, levelname="WARNING", levelno=30, msg="test"):
        """Create a mock log record without importing logging directly."""
        record = Mock()
        record.levelname = levelname
        record.levelno = levelno
        record.getMessage.return_value = msg
        record.exc_info = None
        return record

    def test_emit_with_known_level(self):
        """Emits log with matching loguru level."""
        from local_deep_research.utilities.log_utils import InterceptHandler

        handler = InterceptHandler()
        record = self._make_log_record("WARNING", 30, "test warning")

        with patch(f"{MODULE}.logger") as mock_logger:
            mock_logger.level.return_value = Mock(name="WARNING")
            mock_logger.opt.return_value = mock_logger
            handler.emit(record)
            mock_logger.opt.assert_called()

    def test_emit_with_unknown_level(self):
        """Falls back to numeric level for unknown level names."""
        from local_deep_research.utilities.log_utils import InterceptHandler

        handler = InterceptHandler()
        record = self._make_log_record("CUSTOM", 42, "custom level msg")

        with patch(f"{MODULE}.logger") as mock_logger:
            mock_logger.level.side_effect = ValueError("Unknown level")
            mock_logger.opt.return_value = mock_logger
            handler.emit(record)
            mock_logger.opt.assert_called()


class TestConfigLogger:
    """Tests for config_logger."""

    def test_milestone_level_already_exists(self):
        """Handles MILESTONE level already existing."""
        from local_deep_research.utilities.log_utils import config_logger

        with patch(f"{MODULE}.logger") as mock_logger:
            mock_logger.level.side_effect = ValueError("Level already exists")
            mock_logger.configure = Mock()
            mock_logger.enable = Mock()
            mock_logger.remove = Mock()
            mock_logger.add = Mock()
            mock_logger.warning = Mock()

            # Should not raise
            config_logger("test", debug=False)

    def test_file_logging_enabled(self):
        """File logging adds file handler when env var set."""
        from local_deep_research.utilities.log_utils import config_logger

        with patch.dict("os.environ", {"LDR_ENABLE_FILE_LOGGING": "true"}):
            with patch(f"{MODULE}.logger") as mock_logger:
                mock_logger.level = Mock(return_value=Mock())
                mock_logger.configure = Mock()
                mock_logger.enable = Mock()
                mock_logger.remove = Mock()
                mock_logger.add = Mock()
                mock_logger.warning = Mock()

                config_logger("test", debug=False)

                # Should have 4 adds: stderr, database_sink, frontend_progress, file
                assert mock_logger.add.call_count == 4

    def test_debug_mode_logs_warning(self):
        """Debug mode logs security warning."""
        from local_deep_research.utilities.log_utils import config_logger

        with patch(f"{MODULE}.logger") as mock_logger:
            mock_logger.level = Mock(return_value=Mock())
            mock_logger.configure = Mock()
            mock_logger.enable = Mock()
            mock_logger.remove = Mock()
            mock_logger.add = Mock()
            mock_logger.warning = Mock()

            config_logger("test", debug=True)

            # Should warn about debug logging
            mock_logger.warning.assert_called()
            warning_msg = mock_logger.warning.call_args_list[0][0][0]
            assert "DEBUG logging is enabled" in warning_msg