From d7d765343efa93036e3833daa9aa666de1d14197 Mon Sep 17 00:00:00 2001 From: Eric Gustin <34000337+EricGustin@users.noreply.github.com> Date: Fri, 30 Jan 2026 15:37:52 -0800 Subject: [PATCH] Fix multiple worker log level bug (#758) When running `arcade_mcp_server` with `workers > 1`, uvicorn spawns worker subprocesses that directly call `create_arcade_mcp_factory()` without going through `main()`. Since `setup_logging()` is only called in `main()`, these subprocesses have no logging configuration, causing: 1. Standard Python logging not intercepted by Loguru 2. DEBUG-level logs from libraries like urllib3 appearing when OTEL is enabled 3. Inconsistent log formats between main process and workers --- > [!NOTE] > **Medium Risk** > Touches process-wide logging initialization for uvicorn worker subprocesses, which can affect log levels/handlers and output across the server. Functional impact is limited to observability but could change verbosity when OTEL or libraries emit logs. > > **Overview** > Fixes multi-worker/reload mode logging by configuring Loguru inside `create_arcade_mcp_factory()` (using `ARCADE_MCP_DEBUG` to set `INFO` vs `DEBUG`) so uvicorn-spawned worker subprocesses get the same logging/interception as `main()`. > > Adds regression tests that assert the factory filters DEBUG logs by default and enables them when `ARCADE_MCP_DEBUG=true`, and bumps `arcade-mcp-server` to `1.15.2`. > > Written by [Cursor Bugbot](https://cursor.com/dashboard?tab=bugbot) for commit 0c262eb9716ecbd589f1524842243a7aed80666e. This will update automatically on new commits. Configure [here](https://cursor.com/dashboard?tab=bugbot). --- .../arcade_mcp_server/worker.py | 14 +-- libs/arcade-mcp-server/pyproject.toml | 2 +- .../arcade_mcp_server/test_worker_factory.py | 101 ++++++++++++++++++ 3 files changed, 110 insertions(+), 7 deletions(-) create mode 100644 libs/tests/arcade_mcp_server/test_worker_factory.py 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)