feat(logging): 新增模型调用日志分类与路由能力

.gitignore

@@ -94,4 +94,7 @@ agent_repository_frontend
 .tokensave
 .playwright-mcp/
 # Added by code-review-graph
-.code-review-graph/
+.code-review-graph/
+
+# Added by Serena MCP
+.serena/

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

backend/utils/logging_utils.py

@@ -77,6 +77,27 @@
         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 @@
     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 @@
     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 @@
         },
     }
 
-    # --- 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
 
 

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

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'<runtime_metadata\b.*</runtime_metadata>',
@@ -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",

sdk/nexent/core/agents/run_agent.py

@@ -23,7 +23,6 @@
 
 
 logger = logging.getLogger("run_agent")
-logger.setLevel(logging.DEBUG)
 
 
 class DeferredAgentRun:

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

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