7a0da7932b
OSV-Scanner (Scheduled) / scan-scheduled (push) Failing after 0s
Create Release / test-gate (push) Has been cancelled
Create Release / release-gate (push) Has been cancelled
Create Release / ci-gate (push) Has been cancelled
Create Release / version-check (push) Has been cancelled
Create Release / e2e-test-gate (push) Has been cancelled
Create Release / responsive-test-gate (push) Has been cancelled
Create Release / compat-test-gate (push) Has been cancelled
Create Release / compose-integration-gate (push) Has been cancelled
Create Release / vulture-gate (push) Has been cancelled
Create Release / build (push) Has been cancelled
Create Release / provenance (push) Has been cancelled
Create Release / prerelease-docker (push) Has been cancelled
Create Release / publish-docker (push) Has been cancelled
Create Release / create-release (push) Has been cancelled
Create Release / cleanup-changelog (push) Has been cancelled
Create Release / trigger-pypi (push) Has been cancelled
Create Release / monitor-pypi (push) Has been cancelled
Create Release / Clean up orphan prerelease tags and signatures (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [research-form] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [research-metrics] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [research-workflow] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [settings-core] (push) Has been cancelled
CodeQL Advanced / Analyze (javascript-typescript) (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [history-news] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [library] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [link-analytics] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [chat-core] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [chat-lifecycle] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [error-benchmark] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [settings-pages] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) (push) Has been cancelled
Docker Tests (Consolidated) / Accessibility Tests (push) Has been cancelled
Docker Tests (Consolidated) / LLM Unit Tests (push) Has been cancelled
Docker Tests (Consolidated) / LLM Example Tests (push) Has been cancelled
Docker Tests (Consolidated) / Production Image Smoke Test (push) Has been cancelled
Docker Tests (Consolidated) / Infrastructure Tests (push) Has been cancelled
OSSF Scorecard / OSSF Security Scorecard Analysis (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [mobile] (push) Has been cancelled
Backwards Compatibility / Verify Encryption Constants (push) Has been cancelled
Backwards Compatibility / PyPI Version Compatibility (push) Has been cancelled
Backwards Compatibility / Database Migration Tests (push) Has been cancelled
CodeQL Advanced / Analyze (python) (push) Has been cancelled
Docker Tests (Consolidated) / detect-changes (push) Has been cancelled
Docker Tests (Consolidated) / Build Test Image (push) Has been cancelled
Docker Tests (Consolidated) / All Pytest Tests + Coverage (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [accessibility] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [api-crud] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [auth-login] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [auth-pages] (push) Has been cancelled
Docker Tests (Consolidated) / UI Tests (Puppeteer) [auth-register] (push) Has been cancelled
804 lines
32 KiB
Python
804 lines
32 KiB
Python
"""
|
|
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="<magenta><bold>"
|
|
)
|
|
|
|
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
|
|
)
|