diff --git a/libs/arcade-mcp-server/arcade_mcp_server/worker.py b/libs/arcade-mcp-server/arcade_mcp_server/worker.py index bd7fa2bc..e4bb6b9e 100644 --- a/libs/arcade-mcp-server/arcade_mcp_server/worker.py +++ b/libs/arcade-mcp-server/arcade_mcp_server/worker.py @@ -15,6 +15,8 @@ from typing import Any import uvicorn from arcade_core.catalog import ToolCatalog +from arcade_core.discovery import discover_tools +from arcade_core.toolkit import ToolkitLoadError from arcade_serve.fastapi import FastAPIWorker, TaskTrackerMiddleware from arcade_serve.fastapi.telemetry import OTELHandler from fastapi import FastAPI @@ -23,6 +25,7 @@ from starlette.requests import Request from starlette.responses import Response from starlette.types import Receive, Scope, Send +from arcade_mcp_server.__main__ import setup_logging from arcade_mcp_server.fastapi.auth_routes import create_auth_router from arcade_mcp_server.fastapi.middleware import AddTrailingSlashToPathMiddleware from arcade_mcp_server.resource_server.base import ResourceServerValidator @@ -300,13 +303,12 @@ def create_arcade_mcp_factory() -> FastAPI: This function is called by uvicorn when using reload mode with an import string. It rediscovers the catalog and reads configuration from environment variables. """ - import os - - from arcade_core.discovery import discover_tools - from arcade_core.toolkit import ToolkitLoadError - - # Read configuration from env vars that were set before running the server + # Configure logging first, before any other imports that might trigger logging. + # This is critical for worker subprocesses (workers > 1) where main() is not called. debug = os.environ.get("ARCADE_MCP_DEBUG", "false").lower() == "true" + log_level = "DEBUG" if debug else "INFO" + setup_logging(level=log_level, stdio_mode=False) + # Read configuration from the remaining env vars that were set before running the server otel_enable = os.environ.get("ARCADE_MCP_OTEL_ENABLE", "false").lower() == "true" tool_package = os.environ.get("ARCADE_MCP_TOOL_PACKAGE") discover_installed = os.environ.get("ARCADE_MCP_DISCOVER_INSTALLED", "false").lower() == "true" diff --git a/libs/arcade-mcp-server/pyproject.toml b/libs/arcade-mcp-server/pyproject.toml index 854158b3..a06edb20 100644 --- a/libs/arcade-mcp-server/pyproject.toml +++ b/libs/arcade-mcp-server/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "arcade-mcp-server" -version = "1.15.1" +version = "1.15.2" description = "Model Context Protocol (MCP) server framework for Arcade.dev" readme = "README.md" authors = [{ name = "Arcade.dev" }] diff --git a/libs/tests/arcade_mcp_server/test_worker_factory.py b/libs/tests/arcade_mcp_server/test_worker_factory.py new file mode 100644 index 00000000..a9abdeda --- /dev/null +++ b/libs/tests/arcade_mcp_server/test_worker_factory.py @@ -0,0 +1,101 @@ +import logging +import os +from io import StringIO + +import pytest +from loguru import logger + + +@pytest.fixture(autouse=True) +def isolate_environment(): + """Isolate environment variables for each test.""" + original_env = os.environ.copy() + yield + os.environ.clear() + os.environ.update(original_env) + + +@pytest.fixture(autouse=True) +def reset_logging(): + """Reset logging state before and after each test.""" + # Store original loguru handlers + original_handlers = logger._core.handlers.copy() + + # Clear any existing handlers from root logger + root_logger = logging.getLogger() + original_root_handlers = root_logger.handlers.copy() + original_root_level = root_logger.level + + yield + + # Restore loguru handlers + logger._core.handlers.clear() + logger._core.handlers.update(original_handlers) + + # Restore root logger state + root_logger.handlers = original_root_handlers + root_logger.level = original_root_level + + +class TestFactoryLoggingConfiguration: + """Tests for logging configuration in create_arcade_mcp_factory. + + These tests verify the factory properly configures logging by checking + the actual logging state after the factory runs. + """ + + def test_factory_filters_debug_logs_by_default(self): + """Verify factory filters DEBUG logs when ARCADE_MCP_DEBUG is not set.""" + os.environ["ARCADE_MCP_DISCOVER_INSTALLED"] = "true" + os.environ.pop("ARCADE_MCP_DEBUG", None) + os.environ["ARCADE_MCP_OTEL_ENABLE"] = "false" + + try: + from arcade_mcp_server.worker import create_arcade_mcp_factory + + create_arcade_mcp_factory() + except RuntimeError: + pass + + # Capture output after factory configures logging + output = StringIO() + logger.remove() + handler_id = logger.add(output, format="{level} | {message}", level="INFO") + + try: + test_logger = logging.getLogger("test.factory") + test_logger.debug("This debug message should be filtered") + test_logger.info("This info message should appear") + + log_output = output.getvalue() + assert "This debug message should be filtered" not in log_output + assert "This info message should appear" in log_output + finally: + logger.remove(handler_id) + + def test_factory_allows_debug_logs_when_env_var_set(self): + """Verify factory allows DEBUG logs when ARCADE_MCP_DEBUG=true.""" + os.environ["ARCADE_MCP_DISCOVER_INSTALLED"] = "true" + os.environ["ARCADE_MCP_DEBUG"] = "true" + os.environ["ARCADE_MCP_OTEL_ENABLE"] = "false" + + try: + from arcade_mcp_server.worker import create_arcade_mcp_factory + + create_arcade_mcp_factory() + except RuntimeError: + pass + + # Capture output after factory configures logging + output = StringIO() + logger.remove() + handler_id = logger.add(output, format="{level} | {message}", level="DEBUG") + + try: + test_logger = logging.getLogger("test.factory.debug") + test_logger.debug("This debug message should appear") + + log_output = output.getvalue() + assert "This debug message should appear" in log_output + finally: + logger.remove(handler_id)