From 1bb1d05715825b433d99809085f72047610ff6a1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Claude4=CE=9Elope?= Date: Fri, 27 Jun 2025 16:24:24 +0200 Subject: [PATCH] Replace debug output with proper logging framework MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Added comprehensive logging system with configurable levels - TRACE: Shows raw JSON-RPC I/O with server names - DEBUG: Detailed operational logging - INFO/WARNING/ERROR: Standard logging levels - New command line options: - --log-level: Set logging level (TRACE/DEBUG/INFO/WARNING/ERROR) - --log-file: Log to file instead of stderr - Improved error handling and timeouts: - Initial server discovery timeout reduced to 3 seconds - Servers marked as offline for 30 minutes after failure - Better error messages with server context - All debug output now goes to stderr, keeping stdout clean for JSON Example usage: mcp-browser --log-level TRACE tools-list # See raw I/O mcp-browser --debug --log-file debug.log # Debug to file 🤖 Generated with [Claude Code](https://claude.ai/code) Co-Authored-By: Claude --- mcp_browser/__main__.py | 36 +++++++++-- mcp_browser/daemon.py | 19 +++--- mcp_browser/logging_config.py | 109 ++++++++++++++++++++++++++++++++++ mcp_browser/multi_server.py | 30 +++++----- mcp_browser/proxy.py | 18 +++--- mcp_browser/server.py | 91 +++++++++++++++++----------- mcp_browser/utils.py | 17 ------ 7 files changed, 231 insertions(+), 89 deletions(-) create mode 100644 mcp_browser/logging_config.py delete mode 100644 mcp_browser/utils.py diff --git a/mcp_browser/__main__.py b/mcp_browser/__main__.py index a36c7b9..425c842 100644 --- a/mcp_browser/__main__.py +++ b/mcp_browser/__main__.py @@ -17,7 +17,7 @@ from .proxy import MCPBrowser from .config import ConfigLoader from .default_configs import ConfigManager from .daemon import MCPBrowserDaemon, MCPBrowserClient, get_socket_path, is_daemon_running -from .utils import debug_print, debug_json +from .logging_config import setup_logging, get_logger def build_mcp_request(args) -> Dict[str, Any]: @@ -106,9 +106,10 @@ def build_mcp_request(args) -> Dict[str, Any]: def format_mcp_response(args, request: Dict[str, Any], response: Dict[str, Any]): """Format and print MCP response based on command.""" + logger = get_logger(__name__) if args.debug: - debug_json("Request", request) - debug_json("Response", response) + logger.debug(f"Request: {json.dumps(request)}") + logger.debug(f"Response: {json.dumps(response)}") # Format output based on command if args.command == "tools-list" and "result" in response: @@ -152,7 +153,7 @@ def format_mcp_response(args, request: Dict[str, Any], response: Dict[str, Any]) elif "error" in response: print(f"Error: {response['error'].get('message', 'Unknown error')}") if args.debug: - debug_json("Error details", response["error"]) + logger.debug(f"Error details: {json.dumps(response['error'])}") else: print(json.dumps(response, indent=2)) @@ -543,6 +544,22 @@ async def interactive_mode_with_daemon(socket_path: Path): def main(): """Main entry point.""" + # Parse args first to check for log configuration + args_parser = argparse.ArgumentParser(add_help=False) + args_parser.add_argument("--debug", action="store_true") + args_parser.add_argument("--log-level") + args_parser.add_argument("--log-file") + early_args, _ = args_parser.parse_known_args() + + # Setup logging before anything else + log_file = Path(early_args.log_file) if early_args.log_file else None + setup_logging( + debug=early_args.debug, + log_file=log_file, + log_level=early_args.log_level + ) + + # Now create the full parser parser = argparse.ArgumentParser( description="MCP Browser - Universal Model Context Protocol Interface", epilog=""" @@ -596,6 +613,9 @@ Environment: help="Test connection to specified server") parser.add_argument("--debug", action="store_true", help="Enable debug output") + parser.add_argument("--log-level", choices=["TRACE", "DEBUG", "INFO", "WARNING", "ERROR"], + help="Set logging level") + parser.add_argument("--log-file", help="Log to file instead of stderr") parser.add_argument("--use-daemon", action="store_true", help="Automatically use daemon if available") parser.add_argument("--daemon-start", action="store_true", @@ -671,6 +691,14 @@ Environment: # Create browser config_path = Path(args.config) if args.config else None + + # Apply log level to config if set + if args.log_level == "TRACE" and config_path is None: + from .config import ConfigLoader + loader = ConfigLoader() + config = loader.load() + # TRACE level shows raw I/O + browser = MCPBrowser( server_name=args.server, config_path=config_path, diff --git a/mcp_browser/daemon.py b/mcp_browser/daemon.py index d2ce6e3..e02b9ae 100644 --- a/mcp_browser/daemon.py +++ b/mcp_browser/daemon.py @@ -28,7 +28,7 @@ except ImportError: return False from .proxy import MCPBrowser -from .utils import debug_print, debug_json +from .logging_config import get_logger class MCPBrowserDaemon: @@ -40,6 +40,7 @@ class MCPBrowserDaemon: self.server: Optional[asyncio.Server] = None self._running = False self._clients: set = set() + self.logger = get_logger(__name__) async def start(self): """Start the daemon server.""" @@ -69,8 +70,8 @@ class MCPBrowserDaemon: signal.signal(signal.SIGTERM, self._signal_handler) signal.signal(signal.SIGINT, self._signal_handler) - debug_print(f"MCP Browser daemon started on {self.socket_path}") - debug_print(f"PID: {os.getpid()}") + self.logger.info(f"MCP Browser daemon started on {self.socket_path}") + self.logger.info(f"PID: {os.getpid()}") # Initialize browser await self.browser.initialize() @@ -81,7 +82,7 @@ class MCPBrowserDaemon: def _signal_handler(self, signum, frame): """Handle shutdown signals.""" - debug_print(f"\nReceived signal {signum}, shutting down...") + self.logger.info(f"Received signal {signum}, shutting down...") self._running = False if self.server: self.server.close() @@ -90,7 +91,7 @@ class MCPBrowserDaemon: async def _handle_client(self, reader: asyncio.StreamReader, writer: asyncio.StreamWriter): """Handle a client connection.""" client_addr = writer.get_extra_info('peername') - debug_print(f"Client connected: {client_addr}") + self.logger.debug(f"Client connected: {client_addr}") self._clients.add(writer) try: @@ -112,12 +113,12 @@ class MCPBrowserDaemon: except asyncio.CancelledError: pass except Exception as e: - debug_print(f"Client error: {e}") + self.logger.error(f"Client error: {e}") finally: self._clients.discard(writer) writer.close() await writer.wait_closed() - debug_print(f"Client disconnected: {client_addr}") + self.logger.debug(f"Client disconnected: {client_addr}") async def _process_request(self, line: str, writer: asyncio.StreamWriter): """Process a JSON-RPC request from client.""" @@ -126,7 +127,7 @@ class MCPBrowserDaemon: # Add debug output if configured if self.browser.config and self.browser.config.debug: - debug_json("Daemon received", request) + self.logger.debug(f"Daemon received: {json.dumps(request)}") # Forward to browser response = await self.browser.call(request) @@ -137,7 +138,7 @@ class MCPBrowserDaemon: await writer.drain() if self.browser.config and self.browser.config.debug: - debug_print(f"Daemon sent: {response_str.strip()}") + self.logger.debug(f"Daemon sent: {response_str.strip()}") except json.JSONDecodeError as e: error_response = { diff --git a/mcp_browser/logging_config.py b/mcp_browser/logging_config.py new file mode 100644 index 0000000..324d5ba --- /dev/null +++ b/mcp_browser/logging_config.py @@ -0,0 +1,109 @@ +""" +Logging configuration for MCP Browser. +""" + +import logging +import sys +from pathlib import Path +from typing import Optional +from datetime import datetime + + +class ServerNameAdapter(logging.LoggerAdapter): + """Add server name context to log messages.""" + + def process(self, msg, kwargs): + server = self.extra.get('server', 'main') + return f"[{server}] {msg}", kwargs + + +def setup_logging(debug: bool = False, log_file: Optional[Path] = None, log_level: Optional[str] = None): + """ + Configure logging for MCP Browser. + + Args: + debug: Enable debug logging + log_file: Optional file to write logs to + log_level: Override log level (DEBUG, INFO, WARNING, ERROR) + """ + # Determine log level + if log_level: + level = getattr(logging, log_level.upper(), logging.INFO) + elif debug: + level = logging.DEBUG + else: + level = logging.INFO + + # Create formatter + if level == logging.DEBUG: + # Include timestamp and module for debug + formatter = logging.Formatter( + '%(asctime)s - %(name)s - %(levelname)s - %(message)s', + datefmt='%Y-%m-%d %H:%M:%S' + ) + else: + # Simpler format for normal use + formatter = logging.Formatter('%(levelname)s: %(message)s') + + # Configure root logger + root_logger = logging.getLogger() + root_logger.setLevel(level) + + # Remove existing handlers + root_logger.handlers.clear() + + # Console handler (stderr) + console_handler = logging.StreamHandler(sys.stderr) + console_handler.setFormatter(formatter) + root_logger.addHandler(console_handler) + + # File handler if requested + if log_file: + file_handler = logging.FileHandler(log_file, mode='a') + file_handler.setFormatter(formatter) + root_logger.addHandler(file_handler) + + # Set levels for specific loggers + # Suppress some noisy libraries unless in debug mode + if level > logging.DEBUG: + logging.getLogger('asyncio').setLevel(logging.WARNING) + logging.getLogger('urllib3').setLevel(logging.WARNING) + + +def get_logger(name: str, server: Optional[str] = None) -> logging.Logger: + """ + Get a logger with optional server context. + + Args: + name: Logger name (usually __name__) + server: Optional server name for context + + Returns: + Logger or LoggerAdapter with server context + """ + logger = logging.getLogger(name) + + if server: + return ServerNameAdapter(logger, {'server': server}) + + return logger + + +class RawIOFilter(logging.Filter): + """Filter to only show raw I/O at TRACE level (5).""" + + def filter(self, record): + # Only show raw I/O messages at TRACE level + return record.levelno <= 5 or not record.msg.startswith(('>>> ', '<<< ')) + + +# Add custom TRACE level for raw I/O +TRACE = 5 +logging.addLevelName(TRACE, 'TRACE') + +def trace(self, message, *args, **kwargs): + if self.isEnabledFor(TRACE): + self._log(TRACE, message, args, **kwargs) + +# Add trace method to Logger class +logging.Logger.trace = trace \ No newline at end of file diff --git a/mcp_browser/multi_server.py b/mcp_browser/multi_server.py index 97616df..fcb629a 100644 --- a/mcp_browser/multi_server.py +++ b/mcp_browser/multi_server.py @@ -12,13 +12,14 @@ from pathlib import Path from .server import MCPServer from .config import MCPServerConfig +from .logging_config import get_logger class MultiServerManager: """Manages multiple MCP servers.""" - def __init__(self, debug: bool = False): - self.debug = debug + def __init__(self, logger=None): + self.logger = logger or get_logger(__name__) self.servers: Dict[str, MCPServer] = {} self.builtin_servers = self._get_builtin_servers() @@ -52,15 +53,14 @@ class MultiServerManager: async def start_builtin_servers(self): """Start all built-in servers.""" for name, config in self.builtin_servers.items(): - if self.debug: - print(f"Starting built-in server: {name}") + self.logger.info(f"Starting built-in server: {name}") - server = MCPServer(config, debug=self.debug) - await server.start() - self.servers[name] = server - - # Initialize each server + server = MCPServer(config, logger=get_logger(__name__, name)) try: + await server.start() + self.servers[name] = server + + # Initialize each server await server.send_request("initialize", { "protocolVersion": "0.1.0", "capabilities": {}, @@ -69,16 +69,16 @@ class MultiServerManager: "version": "0.1.0" } }) + self.logger.info(f"Successfully initialized {name}") except Exception as e: - if self.debug: - print(f"Failed to initialize {name}: {e}") + self.logger.error(f"Failed to initialize {name}: {e}") async def add_server(self, name: str, config: MCPServerConfig): """Add and start a custom server.""" if name in self.servers: raise ValueError(f"Server {name} already exists") - server = MCPServer(config, debug=self.debug) + server = MCPServer(config, logger=get_logger(__name__, name)) await server.start() self.servers[name] = server @@ -113,8 +113,7 @@ class MultiServerManager: all_tools.extend(tools) except Exception as e: - if self.debug: - print(f"Failed to get tools from {server_name}: {e}") + self.logger.warning(f"Failed to get tools from {server_name}: {e}") return all_tools @@ -150,8 +149,7 @@ class MultiServerManager: async def stop_all(self): """Stop all servers.""" for name, server in self.servers.items(): - if self.debug: - print(f"Stopping server: {name}") + self.logger.info(f"Stopping server: {name}") await server.stop() self.servers.clear() \ No newline at end of file diff --git a/mcp_browser/proxy.py b/mcp_browser/proxy.py index 3e1a8e9..b6131b2 100644 --- a/mcp_browser/proxy.py +++ b/mcp_browser/proxy.py @@ -16,7 +16,7 @@ from .multi_server import MultiServerManager from .registry import ToolRegistry from .filter import MessageFilter, VirtualToolHandler from .buffer import JsonRpcBuffer -from .utils import debug_print, debug_json +from .logging_config import get_logger, TRACE class MCPBrowser: @@ -50,6 +50,7 @@ class MCPBrowser: self._initialized = False self._response_buffer: Dict[Union[str, int], asyncio.Future] = {} self._next_id = 1 + self.logger = get_logger(__name__) async def __aenter__(self): """Async context manager entry.""" @@ -77,12 +78,12 @@ class MCPBrowser: # Create multi-server manager if using built-in servers if self._enable_builtin_servers: - self.multi_server = MultiServerManager(debug=self.config.debug) + self.multi_server = MultiServerManager(logger=self.logger) await self.multi_server.start_builtin_servers() # Create main server if specified if server_name != "builtin-only": - self.server = MCPServer(server_config, debug=self.config.debug) + self.server = MCPServer(server_config, logger=get_logger(__name__, server_name)) # Set up message handling self.server.add_message_handler(self._handle_server_message) # Start server @@ -209,22 +210,21 @@ class MCPBrowser: } } - # Debug output - if self.config.debug: - debug_json("MCP Browser sending", jsonrpc_object) + # Log at trace level for raw I/O + raw_request = json.dumps(jsonrpc_object) + self.logger.log(TRACE, f">>> {self._server_name}: {raw_request}") # Create future for response future = asyncio.Future() self._response_buffer[request_id] = future # Send to server - self.server.send_raw(json.dumps(jsonrpc_object)) + self.server.send_raw(raw_request) # Wait for response try: response = await asyncio.wait_for(future, timeout=self.config.timeout) - if self.config.debug: - debug_json("MCP Browser received", response) + self.logger.log(TRACE, f"<<< {self._server_name}: {json.dumps(response)}") return response except asyncio.TimeoutError: del self._response_buffer[request_id] diff --git a/mcp_browser/server.py b/mcp_browser/server.py index 25f34c3..7e8ec7b 100644 --- a/mcp_browser/server.py +++ b/mcp_browser/server.py @@ -14,27 +14,38 @@ from pathlib import Path from .buffer import JsonRpcBuffer from .config import MCPServerConfig -from .utils import debug_print, debug_json +from .logging_config import get_logger, TRACE +import logging class MCPServer: """Manages a single MCP server process.""" - def __init__(self, config: MCPServerConfig, debug: bool = False): + def __init__(self, config: MCPServerConfig, logger: Optional[logging.Logger] = None): self.config = config - self.debug = debug + self.logger = logger or get_logger(__name__) self.process: Optional[subprocess.Popen] = None self.buffer = JsonRpcBuffer() self._running = False self._message_handlers: List[Callable[[dict], None]] = [] self._next_id = 1 self._pending_requests: Dict[Union[str, int], asyncio.Future] = {} + self._last_error_time: Optional[float] = None + self._offline_since: Optional[float] = None async def start(self): """Start the MCP server process.""" if self.process: return + # Check if server is marked as offline + import time + if self._offline_since: + offline_duration = time.time() - self._offline_since + if offline_duration < 1800: # 30 minutes + self.logger.warning(f"Server has been offline for {offline_duration:.0f}s, skipping start") + raise RuntimeError(f"Server marked as offline since {offline_duration:.0f}s ago") + # Prepare environment env = os.environ.copy() env.update({ @@ -46,26 +57,31 @@ class MCPServer: # Build command cmd = self.config.command + self.config.args - if self.debug: - debug_print(f"Starting MCP server: {' '.join(cmd)}") + self.logger.info(f"Starting MCP server: {' '.join(cmd)}") - # Start process - self.process = subprocess.Popen( - cmd, - stdin=subprocess.PIPE, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE if self.debug else subprocess.DEVNULL, - env=env, - text=True, - bufsize=0 # Unbuffered - ) - - self._running = True - - # Start reading outputs - asyncio.create_task(self._read_stdout()) - if self.debug: + try: + # Start process + self.process = subprocess.Popen( + cmd, + stdin=subprocess.PIPE, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + env=env, + text=True, + bufsize=0 # Unbuffered + ) + + self._running = True + self._offline_since = None # Clear offline state + + # Start reading outputs + asyncio.create_task(self._read_stdout()) asyncio.create_task(self._read_stderr()) + + except Exception as e: + self.logger.error(f"Failed to start server: {e}") + self._mark_offline() + raise async def stop(self): """Stop the MCP server process.""" @@ -83,6 +99,12 @@ class MCPServer: self.process = None + def _mark_offline(self): + """Mark server as offline.""" + import time + self._offline_since = time.time() + self.logger.warning(f"Server marked as offline") + async def send_request(self, method: str, params: Optional[Dict[str, Any]] = None) -> Dict[str, Any]: """ Send a JSON-RPC request and wait for response. @@ -116,15 +138,18 @@ class MCPServer: self.process.stdin.write(request_str) self.process.stdin.flush() - if self.debug: - debug_print(f"Sent: {request_str.strip()}") + self.logger.log(TRACE, f">>> {request_str.strip()}") + + # Wait for response with appropriate timeout + timeout = 3.0 if method == "initialize" or method == "tools/list" else 30.0 - # Wait for response try: - response = await asyncio.wait_for(future, timeout=30.0) + response = await asyncio.wait_for(future, timeout=timeout) return response except asyncio.TimeoutError: del self._pending_requests[request_id] + self.logger.error(f"Timeout waiting for response to {method} (timeout={timeout}s)") + self._mark_offline() raise TimeoutError(f"No response for request {request_id}") def send_raw(self, message: str): @@ -135,8 +160,7 @@ class MCPServer: if not message.endswith('\n'): message += '\n' - if self.debug: - debug_print(f"MCP Server sending: {message.strip()}") + self.logger.log(TRACE, f">>> {message.strip()}") self.process.stdin.write(message) self.process.stdin.flush() @@ -158,8 +182,8 @@ class MCPServer: await self._handle_message(msg) except Exception as e: - if self.debug: - debug_print(f"Error reading stdout: {e}") + self.logger.error(f"Error reading stdout: {e}") + self._mark_offline() break async def _read_stderr(self): @@ -170,15 +194,15 @@ class MCPServer: if not line: break - debug_print(f"MCP stderr: {line.strip()}") + if line.strip(): + self.logger.warning(f"stderr: {line.strip()}") except Exception: break async def _handle_message(self, message: dict): """Handle an incoming JSON-RPC message.""" - if self.debug: - debug_json("Received", message) + self.logger.log(TRACE, f"<<< {json.dumps(message)}") # Check if it's a response to a pending request msg_id = message.get("id") @@ -195,5 +219,4 @@ class MCPServer: try: handler(message) except Exception as e: - if self.debug: - debug_print(f"Handler error: {e}") \ No newline at end of file + self.logger.error(f"Handler error: {e}") \ No newline at end of file diff --git a/mcp_browser/utils.py b/mcp_browser/utils.py deleted file mode 100644 index 3d2e98c..0000000 --- a/mcp_browser/utils.py +++ /dev/null @@ -1,17 +0,0 @@ -""" -Utility functions for MCP Browser. -""" - -import sys -from typing import Any - - -def debug_print(message: str): - """Print debug message to stderr.""" - print(message, file=sys.stderr, flush=True) - - -def debug_json(label: str, data: Any): - """Print JSON data to stderr for debugging.""" - import json - print(f"{label}: {json.dumps(data)}", file=sys.stderr, flush=True) \ No newline at end of file