""" Extended tests for utilities/log_utils.py logging utilities. Tests cover: - _get_research_id extraction from record extra, Flask g, and fallback to None - database_sink queuing behavior for background threads and missing app context - frontend_progress_sink skipping when no research_id and emitting when present - flush_log_queue processing all queued entries - config_logger enabling/disabling file logging based on LDR_ENABLE_FILE_LOGGING """ import os import queue import threading from datetime import datetime from unittest.mock import Mock, patch class TestGetResearchIdExtended: """Extended tests for _get_research_id function.""" def test_returns_none_when_no_record_and_no_app_context(self): """Should return None when record is None and no Flask app context.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module with patch.object(module, "has_app_context", return_value=False): result = _get_research_id(record=None) assert result is None def test_extracts_from_record_extra_research_id(self): """Should extract research_id from record['extra']['research_id'].""" from local_deep_research.utilities.log_utils import _get_research_id record = { "extra": {"research_id": "abc-123-def"}, } # Should not even need Flask context since record has the id with patch( "local_deep_research.utilities.log_utils.has_app_context", return_value=False, ): result = _get_research_id(record=record) assert result == "abc-123-def" def test_extracts_from_flask_g_when_no_record(self): """Should extract research_id from Flask g.research_id when no record.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module mock_g = Mock() mock_g.get.return_value = "flask-uuid-456" with patch.object(module, "has_app_context", return_value=True): with patch.object(module, "g", mock_g): result = _get_research_id(record=None) assert result == "flask-uuid-456" mock_g.get.assert_called_with("research_id") def test_extracts_from_flask_g_when_record_has_no_research_id(self): """Should fall back to Flask g when record exists but has no research_id in extra.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module record = { "extra": {"some_other_key": "value"}, } mock_g = Mock() mock_g.get.return_value = "g-uuid-789" with patch.object(module, "has_app_context", return_value=True): with patch.object(module, "g", mock_g): result = _get_research_id(record=record) assert result == "g-uuid-789" def test_record_extra_takes_priority_over_flask_g(self): """Record extra research_id should be preferred over Flask g.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module record = { "extra": {"research_id": "record-id"}, } mock_g = Mock() mock_g.get.return_value = "flask-id" with patch.object(module, "has_app_context", return_value=True): with patch.object(module, "g", mock_g): result = _get_research_id(record=record) # Record should take priority assert result == "record-id" # g.get should NOT have been called since record matched first mock_g.get.assert_not_called() def test_returns_none_when_record_has_empty_extra(self): """Should return None when record has empty extra and no app context.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module record = {"extra": {}} with patch.object(module, "has_app_context", return_value=False): result = _get_research_id(record=record) assert result is None def test_returns_none_when_record_has_no_extra_key(self): """Should return None when record dict does not contain 'extra'.""" from local_deep_research.utilities.log_utils import _get_research_id import local_deep_research.utilities.log_utils as module record = {"message": "test"} with patch.object(module, "has_app_context", return_value=False): result = _get_research_id(record=record) assert result is None def _make_mock_message( message="Test message", module_name="test_module", function_name="test_func", line=42, level_name="INFO", extra=None, time=None, ): """Helper to create a mock loguru Message with realistic record structure.""" if extra is None: extra = {} if time is None: time = datetime.now() mock_level = Mock() mock_level.name = level_name mock_time = Mock() mock_time.isoformat.return_value = ( time.isoformat() if isinstance(time, datetime) else str(time) ) mock_msg = Mock() mock_msg.record = { "time": mock_time if not isinstance(time, datetime) else time, "message": message, "name": module_name, "function": function_name, "line": line, "level": mock_level, "extra": extra, } return mock_msg class TestDatabaseSinkExtended: """Extended tests for database_sink queuing behavior.""" def test_queues_log_when_not_in_main_thread(self): """Should queue the log entry when running in a background thread.""" from local_deep_research.utilities.log_utils import database_sink import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message( extra={"research_id": "bg-uuid", "username": "alice"} ) mock_thread = Mock() mock_thread.name = "WorkerThread-1" with patch.object(module, "has_app_context", return_value=True): with patch.object( threading, "current_thread", return_value=mock_thread ): with patch.object(module, "_log_queue") as mock_queue: database_sink(mock_message) mock_queue.put_nowait.assert_called_once() queued_entry = mock_queue.put_nowait.call_args[0][0] assert queued_entry["message"] == "Test message" assert queued_entry["research_id"] == "bg-uuid" assert queued_entry["username"] == "alice" def test_queues_log_when_no_app_context(self): """Should queue the log entry when not in Flask app context.""" from local_deep_research.utilities.log_utils import database_sink import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message(extra={"research_id": "rid-1"}) with patch.object(module, "has_app_context", return_value=False): with patch.object(module, "_log_queue") as mock_queue: database_sink(mock_message) mock_queue.put_nowait.assert_called_once() def test_writes_directly_in_main_thread_with_app_context(self): """Should write directly to database when in main thread with app context.""" from local_deep_research.utilities.log_utils import database_sink import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message( extra={"research_id": "direct-uuid", "username": "bob"} ) mock_thread = Mock() mock_thread.name = "MainThread" with patch.object(module, "has_app_context", return_value=True): with patch.object( threading, "current_thread", return_value=mock_thread ): with patch.object( module, "_write_log_to_database" ) as mock_write: database_sink(mock_message) mock_write.assert_called_once() log_entry = mock_write.call_args[0][0] assert log_entry["message"] == "Test message" assert log_entry["research_id"] == "direct-uuid" def test_drops_log_when_queue_is_full(self): """Should silently drop the log when the queue is full.""" from local_deep_research.utilities.log_utils import database_sink import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message() with patch.object(module, "has_app_context", return_value=False): with patch.object(module, "_log_queue") as mock_queue: mock_queue.put_nowait.side_effect = queue.Full() # Should not raise database_sink(mock_message) def test_log_entry_contains_all_required_fields(self): """The queued log entry dict should contain all expected fields.""" from local_deep_research.utilities.log_utils import database_sink import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message( message="detailed log", module_name="my_module", function_name="my_func", line=99, level_name="WARNING", extra={"username": "charlie"}, ) with patch.object(module, "has_app_context", return_value=False): with patch.object(module, "_log_queue") as mock_queue: database_sink(mock_message) queued_entry = mock_queue.put_nowait.call_args[0][0] assert queued_entry["message"] == "detailed log" assert queued_entry["module"] == "my_module" assert queued_entry["function"] == "my_func" assert queued_entry["line_no"] == 99 assert queued_entry["level"] == "WARNING" assert queued_entry["username"] == "charlie" assert "timestamp" in queued_entry assert "research_id" in queued_entry class TestFrontendProgressSinkExtended: """Extended tests for frontend_progress_sink.""" def test_does_nothing_when_no_research_id(self): """Should return early without emitting when no research_id.""" from local_deep_research.utilities.log_utils import ( frontend_progress_sink, ) import local_deep_research.utilities.log_utils as module mock_message = _make_mock_message(extra={}) with patch.object(module, "_get_research_id", return_value=None): with patch.object(module, "SocketIOService") as mock_socket_cls: frontend_progress_sink(mock_message) mock_socket_cls.return_value.emit_to_subscribers.assert_not_called() def test_emits_to_subscribers_when_research_id_present(self): """Should call emit_to_subscribers with correct args when research_id exists.""" from local_deep_research.utilities.log_utils import ( frontend_progress_sink, ) import local_deep_research.utilities.log_utils as module mock_time = Mock() mock_time.isoformat.return_value = "2026-02-25T10:00:00" mock_level = Mock() mock_level.name = "INFO" mock_message = Mock() mock_message.record = { "message": "Step 3 of 5", "level": mock_level, "time": mock_time, "extra": {"research_id": "emit-uuid"}, } with patch.object(module, "_get_research_id", return_value="emit-uuid"): with patch.object(module, "SocketIOService") as mock_socket_cls: mock_instance = Mock() mock_socket_cls.return_value = mock_instance frontend_progress_sink(mock_message) mock_instance.emit_to_subscribers.assert_called_once() args = mock_instance.emit_to_subscribers.call_args assert args[0][0] == "progress" assert args[0][1] == "emit-uuid" # Check the data structure data = args[0][2] assert "log_entry" in data assert data["log_entry"]["message"] == "Step 3 of 5" assert data["log_entry"]["type"] == "INFO" assert data["log_entry"]["time"] == "2026-02-25T10:00:00" # enable_logging should be False assert args[1]["enable_logging"] is False def test_emits_with_logging_disabled(self): """Should pass enable_logging=False to avoid deadlocks.""" from local_deep_research.utilities.log_utils import ( frontend_progress_sink, ) import local_deep_research.utilities.log_utils as module mock_time = Mock() mock_time.isoformat.return_value = "2026-01-01T00:00:00" mock_level = Mock() mock_level.name = "DEBUG" mock_message = Mock() mock_message.record = { "message": "test", "level": mock_level, "time": mock_time, "extra": {}, } with patch.object(module, "_get_research_id", return_value="some-id"): with patch.object(module, "SocketIOService") as mock_socket_cls: mock_instance = Mock() mock_socket_cls.return_value = mock_instance frontend_progress_sink(mock_message) call_kwargs = mock_instance.emit_to_subscribers.call_args[1] assert call_kwargs["enable_logging"] is False def test_policy_audit_lines_never_reach_websocket(self): """SECURITY.md guarantee: ``policy_audit=True`` log lines must NOT be forwarded to WebSocket subscribers, even when a research_id is bound. policy_audit lines carry engine names + reason codes that would leak the active egress scope to a cross-origin observer under CORS=*. Today these lines don't bind a research_id (so the research_id guard already skips them), but the SECURITY.md doc promises the filter holds even if a future call site binds BOTH — this pins that promise. """ from local_deep_research.utilities.log_utils import ( frontend_progress_sink, ) import local_deep_research.utilities.log_utils as module mock_time = Mock() mock_time.isoformat.return_value = "2026-06-04T00:00:00" mock_level = Mock() mock_level.name = "WARNING" mock_message = Mock() mock_message.record = { "message": "engine denied by egress policy", "level": mock_level, "time": mock_time, # The dangerous case: a policy_audit line that ALSO carries a # research_id, so it survives the research_id guard and reaches # the policy_audit filter. "extra": {"policy_audit": True, "research_id": "audit-uuid"}, } with patch.object( module, "_get_research_id", return_value="audit-uuid" ): with patch.object(module, "SocketIOService") as mock_socket_cls: mock_instance = Mock() mock_socket_cls.return_value = mock_instance frontend_progress_sink(mock_message) # Must be dropped before any WebSocket emit. mock_instance.emit_to_subscribers.assert_not_called() class TestFlushLogQueueExtended: """Extended tests for flush_log_queue.""" def test_processes_all_queued_entries(self): """Should process every entry from the queue until empty.""" from local_deep_research.utilities.log_utils import flush_log_queue import local_deep_research.utilities.log_utils as module entries = [ { "timestamp": datetime.now(), "message": f"Log {i}", "module": "mod", "function": "f", "line_no": i, "level": "INFO", "research_id": None, "username": "user1", } for i in range(3) ] with patch.object(module, "_log_queue") as mock_queue: mock_queue.empty.side_effect = [False, False, False, True] mock_queue.get_nowait.side_effect = entries with patch.object(module, "_write_log_to_database") as mock_write: flush_log_queue() assert mock_write.call_count == 3 # Verify each entry was passed for i, call_obj in enumerate(mock_write.call_args_list): assert call_obj[0][0]["message"] == f"Log {i}" def test_handles_empty_queue(self): """Should do nothing when queue is already empty.""" from local_deep_research.utilities.log_utils import flush_log_queue import local_deep_research.utilities.log_utils as module with patch.object(module, "_log_queue") as mock_queue: mock_queue.empty.return_value = True with patch.object(module, "_write_log_to_database") as mock_write: flush_log_queue() mock_write.assert_not_called() def test_handles_queue_empty_exception_during_get(self): """Should handle queue.Empty raised during get_nowait gracefully.""" from local_deep_research.utilities.log_utils import flush_log_queue import local_deep_research.utilities.log_utils as module with patch.object(module, "_log_queue") as mock_queue: mock_queue.empty.side_effect = [False, True] mock_queue.get_nowait.side_effect = queue.Empty() # Should not raise flush_log_queue() def test_handles_write_exception_and_continues(self): """Should catch exceptions from _write_log_to_database and continue.""" from local_deep_research.utilities.log_utils import flush_log_queue import local_deep_research.utilities.log_utils as module entries = [ { "timestamp": datetime.now(), "message": "will fail", "module": "m", "function": "f", "line_no": 1, "level": "INFO", "research_id": None, "username": None, }, { "timestamp": datetime.now(), "message": "will succeed", "module": "m", "function": "f", "line_no": 2, "level": "INFO", "research_id": None, "username": None, }, ] with patch.object(module, "_log_queue") as mock_queue: mock_queue.empty.side_effect = [False, False, True] mock_queue.get_nowait.side_effect = entries with patch.object(module, "_write_log_to_database") as mock_write: # First call raises, second succeeds mock_write.side_effect = [Exception("DB error"), None] # Should not raise flush_log_queue() assert mock_write.call_count == 2 def test_logs_flush_count_when_entries_flushed(self): """Should log debug message with flushed count when entries are processed.""" from local_deep_research.utilities.log_utils import flush_log_queue import local_deep_research.utilities.log_utils as module entry = { "timestamp": datetime.now(), "message": "log", "module": "m", "function": "f", "line_no": 1, "level": "INFO", "research_id": None, "username": None, } with patch.object(module, "_log_queue") as mock_queue: mock_queue.empty.side_effect = [False, True] mock_queue.get_nowait.return_value = entry with patch.object(module, "_write_log_to_database"): with patch.object(module, "logger") as mock_logger: flush_log_queue() mock_logger.debug.assert_called_once() assert "1" in mock_logger.debug.call_args[0][0] class TestConfigLoggerExtended: """Extended tests for config_logger file logging behavior.""" def test_enables_file_logging_when_env_var_true(self): """Should add a file handler when LDR_ENABLE_FILE_LOGGING=true.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict(os.environ, {"LDR_ENABLE_FILE_LOGGING": "true"}): with patch.object(module, "logger") as mock_logger: config_logger("test_app") # Should have 4 add calls: stderr, database, frontend, file assert mock_logger.add.call_count == 4 # The file handler should be the last one added file_add_call = mock_logger.add.call_args_list[3] # First arg should be a Path object (the log file path) log_file_path = file_add_call[0][0] assert "test_app.log" in str(log_file_path) def test_does_not_add_file_handler_by_default(self): """Should NOT add file handler when LDR_ENABLE_FILE_LOGGING is not set.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": ""}, clear=False ): with patch.object(module, "logger") as mock_logger: config_logger("test_app") # Should have exactly 3 add calls: stderr, database, frontend assert mock_logger.add.call_count == 3 def test_does_not_add_file_handler_when_env_var_false(self): """Should NOT add file handler when LDR_ENABLE_FILE_LOGGING=false.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict(os.environ, {"LDR_ENABLE_FILE_LOGGING": "false"}): with patch.object(module, "logger") as mock_logger: config_logger("test_app") assert mock_logger.add.call_count == 3 def test_enables_file_logging_case_insensitive(self): """LDR_ENABLE_FILE_LOGGING should be case-insensitive (TRUE, True, etc).""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict(os.environ, {"LDR_ENABLE_FILE_LOGGING": "TRUE"}): with patch.object(module, "logger") as mock_logger: config_logger("test_app") # Should add 4 sinks including file assert mock_logger.add.call_count == 4 def test_diagnose_true_requires_both_debug_and_optin(self): """diagnose=True requires BOTH debug=True AND LDR_LOGURU_DIAGNOSE opt-in. With both set, the local stderr sink renders frame locals, but the persisted DB sink and the browser-facing frontend sink are forced diagnose=False regardless (#4182). """ import sys from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": "", "LDR_LOGURU_DIAGNOSE": "true"}, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=True) by_sink = { c.args[0]: c.kwargs.get("diagnose") for c in mock_logger.add.call_args_list } assert by_sink[sys.stderr] is True assert by_sink[module.database_sink] is False assert by_sink[module.frontend_progress_sink] is False def test_file_sink_never_gets_diagnose(self): """The file sink must never render frame locals — it is persistent and unencrypted, so (like the DB and frontend sinks) it is forced diagnose=False regardless of the opt-in. Only the ephemeral stderr sink ever honors LDR_LOGURU_DIAGNOSE (#4182). """ import sys from pathlib import Path from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module # Opt-in OFF: every sink is diagnose=False. with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": "true", "LDR_LOGURU_DIAGNOSE": ""}, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=True) assert mock_logger.add.call_count == 4 for add_call in mock_logger.add.call_args_list: assert add_call[1].get("diagnose") is False # Opt-in ON: only stderr renders frame locals; DB, frontend, AND # the file sink stay diagnose=False. with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": "true", "LDR_LOGURU_DIAGNOSE": "true"}, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=True) assert mock_logger.add.call_count == 4 by_sink = { c.args[0]: c.kwargs.get("diagnose") for c in mock_logger.add.call_args_list } assert by_sink[sys.stderr] is True assert by_sink[module.database_sink] is False assert by_sink[module.frontend_progress_sink] is False file_diagnose = [ d for s, d in by_sink.items() if isinstance(s, Path) ] assert file_diagnose == [False] def test_diagnose_off_when_debug_without_optin(self): """debug=True alone must NOT enable diagnose (localvar leak, issue #4185). Without the explicit LDR_LOGURU_DIAGNOSE opt-in, enabling LDR_APP_DEBUG must keep diagnose=False on every sink so exception tracebacks do not dump frame-local credentials. """ from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": "", "LDR_LOGURU_DIAGNOSE": ""}, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=True) assert mock_logger.add.call_args_list # sinks were added for add_call in mock_logger.add.call_args_list: assert add_call[1].get("diagnose") is False def test_non_debug_mode_sets_diagnose_false(self): """When debug=False (default), all sinks should have diagnose=False.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict( os.environ, {"LDR_ENABLE_FILE_LOGGING": "", "LDR_LOGURU_DIAGNOSE": "true"}, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=False) # Even with the opt-in set, diagnose stays off unless debug too. for add_call in mock_logger.add.call_args_list: assert add_call[1].get("diagnose") is False def test_diagnose_optin_tolerates_surrounding_whitespace(self): """LDR_LOGURU_DIAGNOSE=' true ' must still enable diagnose. Env vars exported via shell scripts, k8s ConfigMaps, or copy-paste commonly carry stray whitespace; without strip() the opt-in would silently fail and the operator would assume diagnose was on. """ from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict( os.environ, { "LDR_ENABLE_FILE_LOGGING": "", "LDR_LOGURU_DIAGNOSE": " true ", }, ): with patch.object(module, "logger") as mock_logger: config_logger("test_app", debug=True) import sys by_sink = { c.args[0]: c.kwargs.get("diagnose") for c in mock_logger.add.call_args_list } # Whitespace-padded opt-in still enables diagnose on the # local stderr sink; DB + frontend stay forced off (#4182). assert by_sink[sys.stderr] is True assert by_sink[module.database_sink] is False assert by_sink[module.frontend_progress_sink] is False def test_creates_milestone_level(self): """Should create MILESTONE log level with level no=26.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.object(module, "logger") as mock_logger: config_logger("test_app") mock_logger.level.assert_called_with( "MILESTONE", no=26, color="" ) def test_handles_existing_milestone_level(self): """Should not raise when MILESTONE level already exists.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.object(module, "logger") as mock_logger: mock_logger.level.side_effect = ValueError( "Level MILESTONE already exists" ) # Should not raise config_logger("test_app") def test_removes_existing_handlers_before_adding(self): """Should call logger.remove() before adding new sinks.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module call_order = [] with patch.object(module, "logger") as mock_logger: mock_logger.remove.side_effect = lambda: call_order.append("remove") mock_logger.add.side_effect = lambda *a, **kw: call_order.append( "add" ) config_logger("test_app") # remove should come before any add assert call_order[0] == "remove" assert "add" in call_order[1:] def test_enables_local_deep_research_logger(self): """Should call logger.enable('local_deep_research').""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.object(module, "logger") as mock_logger: config_logger("test_app") mock_logger.enable.assert_called_with("local_deep_research") def test_file_logging_warns_about_unencrypted_logs(self): """When file logging is enabled, should log a warning about security.""" from local_deep_research.utilities.log_utils import config_logger import local_deep_research.utilities.log_utils as module with patch.dict(os.environ, {"LDR_ENABLE_FILE_LOGGING": "true"}): with patch.object(module, "logger") as mock_logger: config_logger("test_app") # Should warn about unencrypted log files mock_logger.warning.assert_called_once() warning_msg = mock_logger.warning.call_args[0][0] assert ( "unencrypted" in warning_msg.lower() or "WARNING" in warning_msg )