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

<!-- CURSOR_SUMMARY -->
---

> [!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`.
> 
> <sup>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).</sup>
<!-- /CURSOR_SUMMARY -->

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"

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

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)