diff --git a/.gitignore b/.gitignore index 72c36ffd8..b06e56b01 100644 --- a/.gitignore +++ b/.gitignore @@ -94,4 +94,7 @@ agent_repository_frontend .tokensave .playwright-mcp/ # Added by code-review-graph -.code-review-graph/ \ No newline at end of file +.code-review-graph/ + +# Added by Serena MCP +.serena/ \ No newline at end of file diff --git a/backend/runtime_service.py b/backend/runtime_service.py index 652ab5915..a4d95bf61 100644 --- a/backend/runtime_service.py +++ b/backend/runtime_service.py @@ -21,11 +21,11 @@ ) -logging.config.dictConfig(get_uvicorn_logging_config(categories=["runtime"])) +logging.config.dictConfig(get_uvicorn_logging_config(categories=["runtime", "model_call"])) configure_elasticsearch_logging() logger = logging.getLogger("runtime") if __name__ == "__main__": logger.info("Starting server initialization...") logger.info(f"APP version is: {APP_VERSION}") - uvicorn.run(app, host="0.0.0.0", port=5014, log_level="info", log_config=get_uvicorn_logging_config(categories=["runtime"])) + uvicorn.run(app, host="0.0.0.0", port=5014, log_level="info", log_config=get_uvicorn_logging_config(categories=["runtime", "model_call"])) diff --git a/backend/utils/logging_utils.py b/backend/utils/logging_utils.py index 7d58aedb5..7eea3d00a 100644 --- a/backend/utils/logging_utils.py +++ b/backend/utils/logging_utils.py @@ -77,6 +77,27 @@ def doRollover(self): super().doRollover() +# Dedicated category for model runtime logs (nexent_model_call.log). +MODEL_CALL_CATEGORY = "model_call" + +# Logger names of the SDK model layer routed to the model_call file. Names are +# kept exactly as defined in the SDK (no rename); routing binds these loggers +# to the model_call file handler directly via the logconfig "loggers" section +# (dictConfig) or explicit handler binding (configure_logging), with +# propagate=False so the records never reach the per-service category files. +MODEL_CALL_LOGGERS = ( + "openai_llm", + "openai_long_context_model", + "nexent.core.models.openai_vlm", + "nexent.core.models.ali_stt_model", + "nexent.core.models.ali_tts_model", + "volc_stt_model", + "volc_tts_model", + # Namespace for model-scoped loggers added on top (e.g. model_call.core_agent). + "model_call", +) + + def _make_file_handler(category: str) -> logging.Handler: """Create a hybrid time+size rotating file handler for a given category. @@ -115,6 +136,32 @@ def _make_console_handler() -> logging.Handler: return handler +def _bind_model_call_loggers(console_handler: logging.Handler, model_file_handler: logging.Handler): + """Bind model-layer loggers to the model_call file handler. + + Every whitelisted logger receives the console + model_call file handlers + and stops propagating, so its records never reach the root handlers (they + would otherwise be written into the service category file as well). The + console instance is shared with root, keeping docker logs behaviour + unchanged (model records still appear on stdout, exactly once). + """ + for name in MODEL_CALL_LOGGERS: + named_logger = logging.getLogger(name) + named_logger.handlers.clear() + named_logger.addHandler(console_handler) + named_logger.addHandler(model_file_handler) + named_logger.propagate = False + + +def _unbind_model_call_loggers(): + """Undo _bind_model_call_loggers (used when model_call is not configured).""" + for name in MODEL_CALL_LOGGERS: + named_logger = logging.getLogger(name) + for handler in list(named_logger.handlers): + named_logger.removeHandler(handler) + named_logger.propagate = True + + def configure_logging(level: int | None = None, categories: list[str] | None = None): """Configure root logger with console + file handlers. @@ -133,12 +180,26 @@ def configure_logging(level: int | None = None, categories: list[str] | None = N root_logger = logging.getLogger() root_logger.handlers.clear() - # Console handler (always present) - root_logger.addHandler(_make_console_handler()) + # One console instance shared between root and the model_call loggers so + # every record is printed exactly once. + console_handler = _make_console_handler() + root_logger.addHandler(console_handler) - # File handler per category + # The model_call file handler is bound ONLY to the whitelisted loggers + # below — never to root, otherwise every non-model record flowing through + # root would leak into the model file. + model_file_handler = None for cat in categories: - root_logger.addHandler(_make_file_handler(cat)) + handler = _make_file_handler(cat) + if cat == MODEL_CALL_CATEGORY: + model_file_handler = handler + else: + root_logger.addHandler(handler) + + if model_file_handler is not None: + _bind_model_call_loggers(console_handler, model_file_handler) + else: + _unbind_model_call_loggers() root_logger.setLevel(level) @@ -197,15 +258,29 @@ def get_uvicorn_logging_config(categories: list[str] | None = None) -> dict: }, } - # --- Root logger: console + all file handlers --- - handler_names = ["console"] + [f"file_{cat}" for cat in categories] + # --- Root logger: console + all file handlers except model_call --- + # file_model_call is instantiated below but bound only to the whitelisted + # loggers in the "loggers" section — never to root — so non-model records + # cannot leak into the model file. + root_handler_names = ["console"] + [ + f"file_{cat}" for cat in categories if cat != MODEL_CALL_CATEGORY + ] config: dict[str, object] = { "version": 1, "disable_existing_loggers": False, "formatters": formatters, "handlers": {**{"console": console_handler}, **file_handlers}, - "root": {"level": level, "handlers": handler_names}, + "root": {"level": level, "handlers": root_handler_names}, } + + # --- Model-layer routing: bind whitelisted loggers to the model_call file --- + # propagate=False keeps their records out of the service category files; + # console is attached as well so stdout behaviour stays unchanged. + if MODEL_CALL_CATEGORY in categories: + config["loggers"] = { + name: {"handlers": ["console", "file_model_call"], "propagate": False} + for name in MODEL_CALL_LOGGERS + } return config diff --git a/deploy/env/.env.example b/deploy/env/.env.example index 7c3b478fe..e0a8e4c0d 100644 --- a/deploy/env/.env.example +++ b/deploy/env/.env.example @@ -325,6 +325,9 @@ FILE_UPLOAD_SIZE_LIMIT=100 # ===== Logging Configuration ===== # Unified across config / runtime / mcp / data_process / northbound services. # Each service writes to its own subdirectory under LOG_DIR. +# The model_call category is written by the runtime service: records from the +# SDK model-layer loggers (LLM/STT/TTS/VLM calls) land in model_call/ instead +# of runtime/, keeping model logs separate from system logs. # When true, force DEBUG level for all category loggers (overrides LOG_LEVEL) IS_DEBUG=false diff --git a/sdk/nexent/core/agents/core_agent.py b/sdk/nexent/core/agents/core_agent.py index acb9e1653..e98f82d9c 100644 --- a/sdk/nexent/core/agents/core_agent.py +++ b/sdk/nexent/core/agents/core_agent.py @@ -46,6 +46,8 @@ logger = logging.getLogger(__name__) +# Model-call scoped logger routed to nexent_model_call.log by the runtime service. +model_logger = logging.getLogger("model_call.core_agent") RUNTIME_METADATA_BLOCK_RE = re.compile( r'', @@ -790,6 +792,7 @@ def _log_model_call_parameters(self, input_messages: List[ChatMessage], stop_seq Additional Args: {args_str}""" + model_logger.debug("MODEL INPUT PARAMETERS\n%s", log_content) self.logger.log_markdown( content=log_content, title="MODEL INPUT PARAMETERS", diff --git a/sdk/nexent/core/agents/run_agent.py b/sdk/nexent/core/agents/run_agent.py index f3d5ea1e3..4c86ac370 100644 --- a/sdk/nexent/core/agents/run_agent.py +++ b/sdk/nexent/core/agents/run_agent.py @@ -23,7 +23,6 @@ logger = logging.getLogger("run_agent") -logger.setLevel(logging.DEBUG) class DeferredAgentRun: diff --git a/sdk/nexent/core/models/openai_llm.py b/sdk/nexent/core/models/openai_llm.py index d15ae7cc9..2e78196e8 100644 --- a/sdk/nexent/core/models/openai_llm.py +++ b/sdk/nexent/core/models/openai_llm.py @@ -773,7 +773,7 @@ def _close_stream_once(): raise if attempt >= self.retry_config.max_attempts: if not is_timeout: - logging.exception( + logger.exception( "Model call failed after %d attempts: %s", attempt, str(e), ) @@ -1051,5 +1051,5 @@ async def check_connectivity(self) -> bool: # If no exception is raised, the connection is successful return True except Exception as e: - logging.error(f"Connection test failed: {str(e)}") + logger.error(f"Connection test failed: {str(e)}") return False diff --git a/test/backend/utils/test_logging_utils.py b/test/backend/utils/test_logging_utils.py index 13918e154..c3a061c75 100644 --- a/test/backend/utils/test_logging_utils.py +++ b/test/backend/utils/test_logging_utils.py @@ -6,10 +6,13 @@ - HybridRotatingFileHandler: rotation triggers (time vs size) and stream-error fallback - configure_logging: IS_DEBUG override of LOG_LEVEL, explicit level passthrough, default categories - get_uvicorn_logging_config: dictConfig contract, IS_DEBUG override, custom categories + - model_call routing: whitelisted SDK model-layer loggers write to the dedicated + model_call file and stop propagating to the service category files - configure_elasticsearch_logging: noisy client loggers demoted to WARNING """ import logging +import logging.config from logging.handlers import TimedRotatingFileHandler from unittest.mock import MagicMock, patch @@ -18,6 +21,7 @@ from backend.utils.logging_utils import ( ColorFormatter, HybridRotatingFileHandler, + MODEL_CALL_LOGGERS, configure_elasticsearch_logging, configure_logging, get_uvicorn_logging_config, @@ -180,12 +184,14 @@ def test_default_categories_create_one_file_handler_each(self, reset_root_logger monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) configure_logging() root = logging.getLogger() - # One StreamHandler (console) + one file handler per default category. + # One StreamHandler (console) + one file handler per default category, + # except model_call: its file handler is bound only to the whitelisted + # model-layer loggers, never to root. default_cats = ["config", "runtime", "northbound", "data_process", "model_call"] - assert len(root.handlers) == len(default_cats) + 1 + assert len(root.handlers) == len(default_cats) # console + 4 category files handler_classes = [type(h).__name__ for h in root.handlers] assert handler_classes.count("StreamHandler") == 1 - assert handler_classes.count("HybridRotatingFileHandler") == len(default_cats) + assert handler_classes.count("HybridRotatingFileHandler") == len(default_cats) - 1 def test_explicit_level_overrides_effective_level(self, reset_root_logger, tmp_path, monkeypatch): monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) @@ -291,6 +297,127 @@ def test_file_handler_paths_under_log_dir(self, tmp_path, monkeypatch): assert file_h["class"].endswith("HybridRotatingFileHandler") +# --------------------------------------------------------------------------- +# model_call routing +# --------------------------------------------------------------------------- + + +def _cleanup_routing_state(): + """Close test-created root handlers and unbind model_call loggers. + + The console instance is shared between root and the model_call loggers, so + handlers attached to the named loggers are removed without closing (they + were already closed via root). + """ + root = logging.getLogger() + for h in list(root.handlers): + root.removeHandler(h) + h.close() + for name in MODEL_CALL_LOGGERS: + named = logging.getLogger(name) + for h in list(named.handlers): + named.removeHandler(h) + named.propagate = True + + +def _read(tmp_path, category: str) -> str: + return (tmp_path / category / f"nexent_{category}.log").read_text(encoding="utf-8") + + +class TestModelCallRouting: + """When model_call is among the categories, whitelisted model-layer loggers + write to the dedicated model_call file and stop propagating.""" + + def test_loggers_section_only_when_model_call_included(self, tmp_path, monkeypatch): + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + cfg_with = get_uvicorn_logging_config(categories=["runtime", "model_call"]) + assert "loggers" in cfg_with + # Other services must keep their current behaviour untouched. + cfg_without = get_uvicorn_logging_config(categories=["config"]) + assert "loggers" not in cfg_without + + def test_named_loggers_bound_to_model_call_file(self, tmp_path, monkeypatch): + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + cfg = get_uvicorn_logging_config(categories=["runtime", "model_call"]) + for name in MODEL_CALL_LOGGERS: + entry = cfg["loggers"][name] + assert entry["handlers"] == ["console", "file_model_call"] + assert entry["propagate"] is False + # Console itself stays unfiltered (docker logs behaviour unchanged). + assert "filters" not in cfg["handlers"]["console"] + assert "filters" not in cfg["handlers"]["file_runtime"] + + def test_whitelist_covers_sdk_model_loggers(self): + assert set(MODEL_CALL_LOGGERS) >= { + "openai_llm", + "openai_long_context_model", + "nexent.core.models.openai_vlm", + "nexent.core.models.ali_stt_model", + "nexent.core.models.ali_tts_model", + "volc_stt_model", + "volc_tts_model", + "model_call", + } + + def test_config_is_dictconfig_instantiable(self, reset_root_logger, tmp_path, monkeypatch): + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + cfg = get_uvicorn_logging_config(categories=["runtime", "model_call"]) + logging.config.dictConfig(cfg) # must not raise + _cleanup_routing_state() + + def test_dictconfig_routes_model_records_to_dedicated_file( + self, reset_root_logger, tmp_path, monkeypatch + ): + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + cfg = get_uvicorn_logging_config(categories=["runtime", "model_call"]) + logging.config.dictConfig(cfg) + try: + logging.getLogger("openai_llm").info("llm event") + logging.getLogger("runtime_service").info("system event") + for h in logging.getLogger().handlers: + h.flush() + model_log = _read(tmp_path, "model_call") + runtime_log = _read(tmp_path, "runtime") + assert "llm event" in model_log + assert "system event" not in model_log + assert "system event" in runtime_log + assert "llm event" not in runtime_log + finally: + _cleanup_routing_state() + + def test_configure_logging_routes_model_records_to_dedicated_file( + self, reset_root_logger, tmp_path, monkeypatch + ): + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + configure_logging(categories=["runtime", "model_call"]) + try: + logging.getLogger("openai_llm").info("llm event") + logging.getLogger("runtime_service").info("system event") + for h in logging.getLogger().handlers: + h.flush() + model_log = _read(tmp_path, "model_call") + runtime_log = _read(tmp_path, "runtime") + assert "llm event" in model_log + assert "system event" not in model_log + assert "system event" in runtime_log + assert "llm event" not in runtime_log + finally: + _cleanup_routing_state() + + def test_named_loggers_do_not_accumulate_handlers( + self, reset_root_logger, tmp_path, monkeypatch + ): + """Calling configure_logging twice must not stack handlers on named loggers.""" + monkeypatch.setattr("backend.utils.logging_utils.LOG_DIR", str(tmp_path)) + configure_logging(categories=["runtime", "model_call"]) + configure_logging(categories=["runtime", "model_call"]) + try: + for name in MODEL_CALL_LOGGERS: + assert len(logging.getLogger(name).handlers) == 2 + finally: + _cleanup_routing_state() + + # --------------------------------------------------------------------------- # configure_elasticsearch_logging # ---------------------------------------------------------------------------