diff --git a/aworld-cli/src/aworld_cli/gateway_cli.py b/aworld-cli/src/aworld_cli/gateway_cli.py index 7502f7ce8..b99b436cc 100644 --- a/aworld-cli/src/aworld_cli/gateway_cli.py +++ b/aworld-cli/src/aworld_cli/gateway_cli.py @@ -20,7 +20,11 @@ from aworld_gateway.config import GatewayConfig from aworld_gateway.http.artifact_service import ArtifactService from aworld_gateway.http.server import create_gateway_app -from aworld_gateway.logging import configure_gateway_logging, get_gateway_logger +from aworld_gateway.logging import ( + GATEWAY_CONSOLE_LOG_ENV, + configure_gateway_logging, + get_gateway_logger, +) from aworld_gateway.registry import ChannelRegistry from aworld_gateway.router import GatewayRouter, LocalCliAgentBackend from aworld_gateway.runtime import GatewayRuntime @@ -190,8 +194,9 @@ def _build_artifact_service( ) -def _enable_aworld_console_logging_for_gateway() -> None: - os.environ["AWORLD_DISABLE_CONSOLE_LOG"] = "false" +def _suppress_gateway_console_logging() -> None: + os.environ["AWORLD_DISABLE_CONSOLE_LOG"] = "true" + os.environ[GATEWAY_CONSOLE_LOG_ENV] = "false" try: from aworld.logs import util as log_util @@ -199,9 +204,17 @@ def _enable_aworld_console_logging_for_gateway() -> None: return aworld_logger = getattr(log_util, "logger", None) - if aworld_logger is None or not getattr(aworld_logger, "disable_console", False): + if aworld_logger is None or getattr(aworld_logger, "disable_console", False): return + log_id = getattr(aworld_logger, "log_id", None) + bound_logger = getattr(aworld_logger, "_logger", None) + if log_id is not None and bound_logger is not None: + try: + bound_logger.remove(log_id) + except Exception: + pass + file_log_config = getattr(aworld_logger, "file_log_config", None) if isinstance(file_log_config, dict): file_log_config = dict(file_log_config) @@ -211,11 +224,18 @@ def _enable_aworld_console_logging_for_gateway() -> None: name=getattr(aworld_logger, "name", "AWorld"), console_level=getattr(aworld_logger, "console_level", "INFO"), formatter=getattr(aworld_logger, "formater", None), - disable_console=False, + disable_console=True, file_log_config=file_log_config, ) +def _restore_env_var(name: str, previous_value: str | None) -> None: + if previous_value is None: + os.environ.pop(name, None) + else: + os.environ[name] = previous_value + + def _configure_gateway_file_logging(*, base_dir: Path) -> Path: log_path = (base_dir / "logs" / "gateway.log").resolve() os.environ["AWORLD_GATEWAY_LOG_PATH"] = str(log_path) @@ -261,59 +281,69 @@ async def serve_gateway( agent_files: list[str] | None, ) -> None: resolved_base_dir = Path.cwd() if base_dir is None else Path(base_dir) - gateway_log_path = _configure_gateway_file_logging(base_dir=resolved_base_dir) - gateway_logger = get_gateway_logger("cli") - _enable_aworld_console_logging_for_gateway() - enable_quiet_gateway_boot() - gateway_logger.info( - "Gateway server boot starting " - f"base_dir={resolved_base_dir.resolve()} log_path={gateway_log_path}" - ) - - from aworld_cli.main import load_all_agents - - await load_all_agents( - remote_backends=remote_backends, - local_dirs=local_dirs, - agent_files=agent_files, - ) - - config = GatewayConfigLoader(base_dir=resolved_base_dir).load_or_init() - artifact_service = _build_artifact_service(base_dir=resolved_base_dir, config=config) - router = GatewayRouter( - session_binding=SessionBinding(), - agent_resolver=AgentResolver(default_agent_id=config.default_agent_id), - agent_backend=LocalCliAgentBackend(), - ) - runtime = GatewayRuntime( - config=config, - registry=ChannelRegistry(), - router=router, - artifact_service=artifact_service, - ) - - await runtime.start() - gateway_logger.info( - "Gateway runtime started " - f"host={config.gateway.host} port={config.gateway.port}" - ) - telegram_adapter = runtime.get_started_channel("telegram") - app = create_gateway_app( - runtime_status=runtime.status(), - artifact_service=artifact_service, - telegram_adapter=telegram_adapter, - telegram_webhook_path=config.channels.telegram.webhook_path, - ) - uvicorn_config = uvicorn.Config( - app=app, - host=config.gateway.host, - port=config.gateway.port, - ) - server = uvicorn.Server(uvicorn_config) - + previous_disable_console_log = os.environ.get("AWORLD_DISABLE_CONSOLE_LOG") + previous_gateway_console_log = os.environ.get(GATEWAY_CONSOLE_LOG_ENV) + gateway_log_path: Path | None = None + _suppress_gateway_console_logging() try: - await server.serve() + gateway_log_path = _configure_gateway_file_logging(base_dir=resolved_base_dir) + gateway_logger = get_gateway_logger("cli") + enable_quiet_gateway_boot() + gateway_logger.info( + "Gateway server boot starting " + f"base_dir={resolved_base_dir.resolve()} log_path={gateway_log_path}" + ) + + from aworld_cli.main import load_all_agents + + await load_all_agents( + remote_backends=remote_backends, + local_dirs=local_dirs, + agent_files=agent_files, + ) + + config = GatewayConfigLoader(base_dir=resolved_base_dir).load_or_init() + artifact_service = _build_artifact_service(base_dir=resolved_base_dir, config=config) + router = GatewayRouter( + session_binding=SessionBinding(), + agent_resolver=AgentResolver(default_agent_id=config.default_agent_id), + agent_backend=LocalCliAgentBackend(), + ) + runtime = GatewayRuntime( + config=config, + registry=ChannelRegistry(), + router=router, + artifact_service=artifact_service, + ) + + await runtime.start() + gateway_logger.info( + "Gateway runtime started " + f"host={config.gateway.host} port={config.gateway.port}" + ) + telegram_adapter = runtime.get_started_channel("telegram") + app = create_gateway_app( + runtime_status=runtime.status(), + artifact_service=artifact_service, + telegram_adapter=telegram_adapter, + telegram_webhook_path=config.channels.telegram.webhook_path, + ) + uvicorn_config = uvicorn.Config( + app=app, + host=config.gateway.host, + port=config.gateway.port, + log_level=str(os.getenv("AWORLD_GATEWAY_UVICORN_LOG_LEVEL") or "warning"), + ) + server = uvicorn.Server(uvicorn_config) + + try: + await server.serve() + finally: + gateway_logger.info("Gateway runtime stopping") + await runtime.stop() + gateway_logger.info("Gateway runtime stopped") finally: - gateway_logger.info("Gateway runtime stopping") - await runtime.stop() - gateway_logger.info("Gateway runtime stopped") + _restore_env_var("AWORLD_DISABLE_CONSOLE_LOG", previous_disable_console_log) + _restore_env_var(GATEWAY_CONSOLE_LOG_ENV, previous_gateway_console_log) + if gateway_log_path is not None: + configure_gateway_logging(log_path=gateway_log_path) diff --git a/aworld_gateway/channels/wechat/connector.py b/aworld_gateway/channels/wechat/connector.py index e1cd9da09..75295feae 100644 --- a/aworld_gateway/channels/wechat/connector.py +++ b/aworld_gateway/channels/wechat/connector.py @@ -127,7 +127,8 @@ async def _default_post_json( timeout_ms: int, ) -> dict[str, object]: request_summary = _summarize_wechat_request_payload(payload) - logger.info( + log_success = logger.debug if endpoint == EP_GET_UPDATES else logger.info + log_success( "WeChat API request " f"endpoint={endpoint} timeout_ms={timeout_ms}" f"{f' {request_summary}' if request_summary else ''}" @@ -149,7 +150,7 @@ async def _default_post_json( ) raise RuntimeError(f"iLink POST {endpoint} HTTP {response.status}: {raw[:200]}") data = json.loads(raw) - logger.info( + log_success( "WeChat API response " f"endpoint={endpoint} http_status={getattr(response, 'status', 'unknown')} " f"ret={data.get('ret', 'missing')} " diff --git a/aworld_gateway/logging.py b/aworld_gateway/logging.py index 887934173..417b2f6e5 100644 --- a/aworld_gateway/logging.py +++ b/aworld_gateway/logging.py @@ -6,7 +6,16 @@ from pathlib import Path GATEWAY_LOGGER_NAME = "aworld.gateway" +GATEWAY_CONSOLE_LOG_ENV = "AWORLD_GATEWAY_CONSOLE_LOG" _GATEWAY_HANDLER_MARKER = "_aworld_gateway_file_handler" +_FALSEY_VALUES = {"0", "false", "no", "off"} + + +def _is_gateway_console_log_enabled() -> bool: + configured = str(os.getenv(GATEWAY_CONSOLE_LOG_ENV) or "").strip().lower() + if configured in _FALSEY_VALUES: + return False + return True def resolve_gateway_log_path(log_path: Path | str | None = None) -> Path: @@ -30,7 +39,7 @@ def configure_gateway_logging(*, log_path: Path | str | None = None) -> Path: gateway_root_logger = logging.getLogger(GATEWAY_LOGGER_NAME) gateway_root_logger.setLevel(logging.INFO) - gateway_root_logger.propagate = True + gateway_root_logger.propagate = _is_gateway_console_log_enabled() for handler in list(gateway_root_logger.handlers): if not getattr(handler, _GATEWAY_HANDLER_MARKER, False): diff --git a/tests/gateway/test_gateway_status_command.py b/tests/gateway/test_gateway_status_command.py index 28f335841..9e573a715 100644 --- a/tests/gateway/test_gateway_status_command.py +++ b/tests/gateway/test_gateway_status_command.py @@ -2,6 +2,7 @@ import asyncio import importlib +import logging import os import sys from types import ModuleType @@ -51,7 +52,7 @@ def test_gateway_channels_list_contains_placeholder_channels( assert rows["web"]["implemented"] is False -def test_enable_aworld_console_logging_for_gateway_reconfigures_disabled_logger( +def test_suppress_gateway_console_logging_reconfigures_enabled_logger( monkeypatch: pytest.MonkeyPatch, ) -> None: class FakeLogger: @@ -83,15 +84,31 @@ def __init__( import aworld.logs.util as log_util - fake_logger = FakeLogger(disable_console=True) + fake_logger = FakeLogger(disable_console=False) monkeypatch.setattr(log_util, "logger", fake_logger) - monkeypatch.setenv("AWORLD_DISABLE_CONSOLE_LOG", "true") + monkeypatch.setenv("AWORLD_DISABLE_CONSOLE_LOG", "false") + monkeypatch.delenv("AWORLD_GATEWAY_CONSOLE_LOG", raising=False) + + gateway_cli._suppress_gateway_console_logging() + + assert os.environ["AWORLD_DISABLE_CONSOLE_LOG"] == "true" + assert os.environ["AWORLD_GATEWAY_CONSOLE_LOG"] == "false" + assert fake_logger.disable_console is True + assert fake_logger.calls[-1]["disable_console"] is True + + +def test_configure_gateway_file_logging_can_suppress_console_propagation( + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + monkeypatch.setenv("AWORLD_GATEWAY_CONSOLE_LOG", "false") + + gateway_cli._configure_gateway_file_logging(base_dir=tmp_path) - gateway_cli._enable_aworld_console_logging_for_gateway() + assert logging.getLogger("aworld.gateway").propagate is False - assert os.environ["AWORLD_DISABLE_CONSOLE_LOG"] == "false" - assert fake_logger.disable_console is False - assert fake_logger.calls[-1]["disable_console"] is False + monkeypatch.setenv("AWORLD_GATEWAY_CONSOLE_LOG", "true") + gateway_cli._configure_gateway_file_logging(base_dir=tmp_path) def test_configure_gateway_file_logging_writes_to_dedicated_gateway_log( @@ -136,7 +153,7 @@ def test_get_gateway_logger_returns_named_child_logger( assert logger.name == f"{GATEWAY_LOGGER_NAME}.child_component" -def test_serve_gateway_enables_console_logging_before_loading_agents( +def test_serve_gateway_suppresses_console_logging_before_loading_agents( monkeypatch: pytest.MonkeyPatch, tmp_path: Path, ) -> None: @@ -145,6 +162,7 @@ def test_serve_gateway_enables_console_logging_before_loading_agents( async def fake_load_all_agents(*, remote_backends, local_dirs, agent_files): observed["disable_console_env"] = os.environ.get("AWORLD_DISABLE_CONSOLE_LOG", "") + observed["gateway_console_env"] = os.environ.get("AWORLD_GATEWAY_CONSOLE_LOG", "") observed["quiet_boot_env"] = os.environ.get("AWORLD_GATEWAY_QUIET_BOOT", "") raise RuntimeError("stop after env check") @@ -163,7 +181,8 @@ async def fake_load_all_agents(*, remote_backends, local_dirs, agent_files): ) ) - assert observed["disable_console_env"] == "false" + assert observed["disable_console_env"] == "true" + assert observed["gateway_console_env"] == "false" assert observed["quiet_boot_env"] == "true" @@ -311,11 +330,12 @@ def get_started_channel(self, channel_name: str): return telegram_adapter class FakeUvicornConfig: - def __init__(self, *, app, host, port): + def __init__(self, *, app, host, port, log_level): calls["uvicorn_config"] = { "app": app, "host": host, "port": port, + "log_level": log_level, } class FakeUvicornServer: @@ -434,8 +454,9 @@ def get_started_channel(self, channel_name: str): return None class FakeUvicornConfig: - def __init__(self, *, app, host, port): + def __init__(self, *, app, host, port, log_level): calls["uvicorn_app"] = app + calls["uvicorn_log_level"] = log_level class FakeUvicornServer: def __init__(self, config): diff --git a/tests/gateway/test_wechat_connector.py b/tests/gateway/test_wechat_connector.py index a2d2220d2..ff92952e5 100644 --- a/tests/gateway/test_wechat_connector.py +++ b/tests/gateway/test_wechat_connector.py @@ -15,6 +15,17 @@ from aworld_gateway.types import OutboundEnvelope +@pytest.fixture(autouse=True) +def _enable_gateway_log_capture( + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + from aworld_gateway.logging import configure_gateway_logging + + monkeypatch.setenv("AWORLD_GATEWAY_CONSOLE_LOG", "true") + configure_gateway_logging(log_path=tmp_path / "gateway.log") + + class _FakeRouter: def __init__(self, *, response_text: str | None = None) -> None: self.calls: list[tuple[object, str | None, object | None]] = [] @@ -1561,6 +1572,64 @@ def post(self, *args, **kwargs): assert result == {"ret": 0, "msgs": [], "get_updates_buf": "buf-1"} +@pytest.mark.asyncio +async def test_default_get_updates_success_logs_at_debug( + caplog: pytest.LogCaptureFixture, + monkeypatch: pytest.MonkeyPatch, + tmp_path: Path, +) -> None: + from aworld_gateway.channels.wechat.connector import _default_get_updates + from aworld_gateway.logging import configure_gateway_logging + + monkeypatch.setenv("AWORLD_GATEWAY_CONSOLE_LOG", "true") + configure_gateway_logging(log_path=tmp_path / "gateway.log") + + class _FakeResponse: + ok = True + status = 200 + + async def text(self) -> str: + return '{"ret":0,"msgs":[],"get_updates_buf":"buf-2"}' + + async def __aenter__(self): + return self + + async def __aexit__(self, exc_type, exc, tb): + return False + + class _FakeSession: + def post(self, *args, **kwargs): + return _FakeResponse() + + caplog.set_level(logging.INFO, logger="aworld.gateway") + + result = await _default_get_updates( + session=_FakeSession(), + base_url="ilink.example.test", + token="wx-token", + sync_buf="buf-1", + timeout_ms=1234, + ) + + assert result["get_updates_buf"] == "buf-2" + assert "WeChat API request endpoint=ilink/bot/getupdates" not in caplog.text + assert "WeChat API response endpoint=ilink/bot/getupdates" not in caplog.text + + caplog.clear() + caplog.set_level(logging.DEBUG, logger="aworld.gateway") + + await _default_get_updates( + session=_FakeSession(), + base_url="ilink.example.test", + token="wx-token", + sync_buf="buf-1", + timeout_ms=1234, + ) + + assert "WeChat API request endpoint=ilink/bot/getupdates" in caplog.text + assert "WeChat API response endpoint=ilink/bot/getupdates" in caplog.text + + @pytest.mark.asyncio async def test_connector_process_message_downloads_image_attachment_and_routes_prompt( monkeypatch: pytest.MonkeyPatch,