""" 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