# #region Test.Logger.TestLogger [C:2] [TYPE Module] # @SEMANTICS: logging, tests, belief_state, cot, json # @PURPOSE: Unit tests for the custom logger CoT JSON formatters and configuration context manager. # @LAYER Tests # @RELATION BINDS_TO -> [Core.Logger.LoggerModule] # @INVARIANT: All required log statements must correctly check the threshold. import logging import pytest from src.core.config_models import LoggingConfig from src.core.logger import ( CotJsonFormatter, belief_scope, configure_logger, get_task_log_level, logger, should_log_task_level, ) @pytest.fixture(autouse=True) def reset_logger_state(): """Reset logger state before each test to avoid cross-test contamination.""" from ss_tools.shared.cot_logger import cot_logger as _cot import logging as _logging config = LoggingConfig( level="DEBUG", task_log_level="DEBUG", enable_belief_state=True ) configure_logger(config) # Re-enable propagation for caplog capture (configure_logger disables it) logger.propagate = True _cot.propagate = True _cot.setLevel(_logging.DEBUG) # Also reset the logger level for caplog to work correctly _logging.getLogger("superset_tools_app").setLevel(_logging.DEBUG) yield # Reset after test too (keep DEBUG for caplog) config = LoggingConfig( level="DEBUG", task_log_level="DEBUG", enable_belief_state=True ) configure_logger(config) logger.propagate = True _cot.propagate = True _cot.setLevel(_logging.DEBUG) def _repropagate(): """Re-enable propagation after configure_logger (which disables it).""" from ss_tools.shared.cot_logger import cot_logger as _c logger.propagate = True _c.propagate = True # #region Test.Logger.TestBeliefScopeLogsReasonReflectAtDebug [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that belief_scope generates REASON and REFLECT CoT markers at DEBUG level. # @PRE: belief_scope is available. caplog fixture is used. Logger configured to DEBUG. # @POST: Logs are verified to contain REASON (entry) and REFLECT (coherence) markers. def test_belief_scope_logs_reason_reflect_at_debug(caplog): """Test that belief_scope generates REASON and REFLECT CoT markers at DEBUG level.""" config = LoggingConfig(level="DEBUG", task_log_level="DEBUG", enable_belief_state=True) configure_logger(config) _repropagate() caplog.set_level("DEBUG") with belief_scope("TestFunction"): logger.info("Doing something important") reason_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'REASON' and getattr(r, 'src', None) == 'TestFunction'] reflect_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'REFLECT' and getattr(r, 'src', None) == 'TestFunction'] info_records = [r for r in caplog.records if r.levelname == 'INFO' and 'Doing something important' in r.getMessage()] assert len(reason_records) >= 1, "REASON marker not found for TestFunction" assert len(reflect_records) >= 1, "REFLECT marker not found for TestFunction" assert len(info_records) >= 1, "INFO log 'Doing something important' not found" config = LoggingConfig(level="DEBUG", task_log_level="DEBUG", enable_belief_state=True) configure_logger(config) _repropagate() # #endregion Test.Logger.TestBeliefScopeLogsReasonReflectAtDebug # #region Test.Logger.TestBeliefScopeErrorHandling [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that belief_scope logs EXPLORE marker on exception. # @PRE: belief_scope is available. caplog fixture is used. Logger configured to DEBUG. # @POST: Logs are verified to contain EXPLORE marker with error context. def test_belief_scope_error_handling(caplog): """Test that belief_scope logs EXPLORE marker on exception.""" # Configure logger to DEBUG level config = LoggingConfig( level="DEBUG", task_log_level="DEBUG", enable_belief_state=True ) configure_logger(config) _repropagate() caplog.set_level("DEBUG") with pytest.raises(ValueError), belief_scope("FailingFunction"): raise ValueError("Something went wrong") explore_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'EXPLORE' and getattr(r, 'src', None) == 'FailingFunction'] assert len(explore_records) >= 1, f"EXPLORE marker not found" assert 'Something went wrong' in explore_records[0].getMessage() or \ 'Something went wrong' in str(getattr(explore_records[0], 'error', '')) config = LoggingConfig(level="DEBUG", task_log_level="DEBUG", enable_belief_state=True) configure_logger(config) _repropagate() # #endregion Test.Logger.TestBeliefScopeErrorHandling # #region Test.Logger.TestBeliefScopeSuccessCoherence [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that belief_scope logs REFLECT marker on success. # @PRE: belief_scope is available. caplog fixture is used. Logger configured to DEBUG. # @POST: Logs are verified to contain REFLECT marker. def test_belief_scope_success_coherence(caplog): """Test that belief_scope logs REFLECT marker on success.""" config = LoggingConfig(level="DEBUG", task_log_level="DEBUG", enable_belief_state=True) configure_logger(config) _repropagate() caplog.set_level("DEBUG") with belief_scope("SuccessFunction"): pass reflect_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'REFLECT' and getattr(r, 'src', None) == 'SuccessFunction'] assert len(reflect_records) >= 1, f"REFLECT marker not found" assert 'completed' in reflect_records[0].getMessage() or \ 'completed' in getattr(reflect_records[0], 'intent', '') # #endregion Test.Logger.TestBeliefScopeSuccessCoherence # #region Test.Logger.TestBeliefScopeReasonNotVisibleAtInfo [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that belief_scope REASON/REFLECT markers are NOT visible at INFO level. # @PRE: belief_scope is available. caplog fixture is used. # @POST: REASON/REFLECT markers are not captured at INFO level. def test_belief_scope_reason_not_visible_at_info(caplog): """Test that belief_scope REASON/REFLECT markers are NOT visible at INFO level.""" caplog.set_level("INFO") with belief_scope("InfoLevelFunction"): logger.info("Doing something important") # The REASON and REFLECT markers are debug-level, so they should NOT appear at INFO reason_records = [ r for r in caplog.records if getattr(r, 'marker', None) == 'REASON' and getattr(r, 'src', None) == 'InfoLevelFunction' ] reflect_records = [ r for r in caplog.records if getattr(r, 'marker', None) == 'REFLECT' and getattr(r, 'src', None) == 'InfoLevelFunction' ] assert len(reason_records) == 0, "REASON marker should not be visible at INFO" assert len(reflect_records) == 0, "REFLECT marker should not be visible at INFO" # But the INFO-level message should be visible info_records = [ r for r in caplog.records if r.levelname == 'INFO' and 'Doing something important' in r.getMessage() ] assert len(info_records) >= 1, "INFO log 'Doing something important' should be visible" # #endregion Test.Logger.TestBeliefScopeReasonNotVisibleAtInfo # #region Test.Logger.TestTaskLogLevelDefault [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that default task log level is INFO. # @PRE: None. # @POST: Default level is INFO. def test_task_log_level_default(): """Test that default task log level is INFO after explicit config.""" config = LoggingConfig(level="INFO", task_log_level="INFO", enable_belief_state=True) configure_logger(config) _repropagate() assert get_task_log_level() == "INFO" # #endregion Test.Logger.TestTaskLogLevelDefault # #region Test.Logger.TestShouldLogTaskLevel [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that should_log_task_level correctly filters log levels. # @PRE: None. # @POST: Filtering works correctly for all level combinations. def test_should_log_task_level(): """Test that should_log_task_level correctly filters log levels.""" config = LoggingConfig(level="INFO", task_log_level="INFO", enable_belief_state=True) configure_logger(config) _repropagate() # task_log_level is now INFO assert should_log_task_level("ERROR") is True, "ERROR should be logged at INFO threshold" assert should_log_task_level("WARNING") is True, "WARNING should be logged at INFO threshold" assert should_log_task_level("INFO") is True, "INFO should be logged at INFO threshold" assert should_log_task_level("DEBUG") is False, "DEBUG should NOT be logged at INFO threshold" # #endregion Test.Logger.TestShouldLogTaskLevel # #region Test.Logger.TestConfigureLoggerTaskLogLevel [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that configure_logger updates task_log_level. # @PRE: LoggingConfig is available. # @POST: task_log_level is updated correctly. def test_configure_logger_task_log_level(): """Test that configure_logger updates task_log_level.""" config = LoggingConfig( level="DEBUG", task_log_level="DEBUG", enable_belief_state=True ) configure_logger(config) assert get_task_log_level() == "DEBUG", "task_log_level should be DEBUG" assert should_log_task_level("DEBUG") is True, "DEBUG should be logged at DEBUG threshold" # Reset to INFO config = LoggingConfig( level="INFO", task_log_level="INFO", enable_belief_state=True ) configure_logger(config) assert get_task_log_level() == "INFO", "task_log_level should be reset to INFO" # #endregion Test.Logger.TestConfigureLoggerTaskLogLevel # #region Test.Logger.TestEnableBeliefStateFlag [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that enable_belief_state flag controls belief_scope entry logging. # @PRE: LoggingConfig is available. caplog fixture is used. # @POST: REASON entry marker suppressed when disabled; REFLECT coherence still logged. def test_enable_belief_state_flag(caplog): """Test that enable_belief_state flag controls belief_scope REASON entry logging.""" # Disable belief state config = LoggingConfig( level="DEBUG", task_log_level="DEBUG", enable_belief_state=False ) configure_logger(config) _repropagate() caplog.set_level("DEBUG") with belief_scope("DisabledFunction"): logger.info("Doing something") reason_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'REASON' and getattr(r, 'src', None) == 'DisabledFunction'] assert len(reason_records) == 0, "REASON entry should not be logged when disabled" reflect_records = [r for r in caplog.records if getattr(r, 'marker', None) == 'REFLECT' and getattr(r, 'src', None) == 'DisabledFunction'] assert len(reflect_records) >= 1, "REFLECT coherence should still be logged" config = LoggingConfig(level="DEBUG", task_log_level="DEBUG", enable_belief_state=True) configure_logger(config) _repropagate() # #endregion Test.Logger.TestEnableBeliefStateFlag # #region Test.Logger.TestCotJsonFormatterOutput [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that CotJsonFormatter produces valid JSON with expected fields. def test_cot_json_formatter_output(): """Test that CotJsonFormatter produces valid JSON with expected fields.""" import json from ss_tools.shared.cot_logger import clear_task_id # Formatters include a bound task ID for operational log correlation. clear_task_id() formatter = CotJsonFormatter() # Create a LogRecord with structured extra data record = logging.LogRecord( name="test.module", level=logging.INFO, pathname="/fake/path.py", lineno=42, msg="Test action", args=(), exc_info=None, ) record.marker = "REASON" record.intent = "Test action" record.src = "TestModule" record.payload = {"key": "value"} output = formatter.format(record) parsed = json.loads(output) assert parsed["level"] == "INFO" assert parsed["marker"] == "REASON" assert parsed["intent"] == "Test action" assert parsed["src"] == "TestModule" assert parsed["payload"] == {"key": "value"} assert "ts" in parsed assert "trace_id" in parsed # #endregion Test.Logger.TestCotJsonFormatterOutput # #region Test.Logger.TestCotJsonFormatterPlainMessage [C:2] [TYPE Function] # @RELATION BINDS_TO -> Test.Logger.TestLogger # @PURPOSE: Test that CotJsonFormatter wraps plain messages (no extra) with default marker. def test_cot_json_formatter_plain_message(): """Test that CotJsonFormatter wraps plain messages with default marker.""" import json formatter = CotJsonFormatter() # Create a LogRecord WITHOUT extra data (plain message) record = logging.LogRecord( name="test.module", level=logging.INFO, pathname="/fake/path.py", lineno=42, msg="Plain info message", args=(), exc_info=None, ) # Set src explicitly to bypass derive_src in a test context record.src = "test.module" output = formatter.format(record) parsed = json.loads(output) assert parsed["level"] == "INFO" assert parsed["marker"] == "REASON" # default for plain messages assert parsed["intent"] == "Plain info message" assert parsed["src"] == "test.module" assert "ts" in parsed assert "trace_id" in parsed # #endregion Test.Logger.TestCotJsonFormatterPlainMessage # #region Test.Logger.TestDeriveSrcAndAgentSrcEnforcement [C:2] [TYPE Function] # @RELATION BINDS_TO -> [CotLoggerModule] # @PURPOSE: Verify derive_src produces qualified names and bad generic src are avoided (core of agent-centric goal). def test_derive_src_and_agent_src_enforcement(): from ss_tools.shared.cot_logger import derive_src # In most real contexts this returns module.something src = derive_src("fallback-test") assert src is not None assert "fallback-test" not in src or src != "superset_tools_app" # Never generic root names in production paths assert src not in {"superset_tools_app", "app_name", "root", ""} # #endregion Test.Logger.TestDeriveSrcAndAgentSrcEnforcement # #endregion Test.Logger.TestLogger