diff --git a/src/webex_bot_mcp/main.py b/src/webex_bot_mcp/main.py index b2ae57f..c89d017 100644 --- a/src/webex_bot_mcp/main.py +++ b/src/webex_bot_mcp/main.py @@ -61,11 +61,16 @@ update_webex_webhook, delete_webex_webhook, ) -# Import version and error handling from common -from webex_bot_mcp.tools.common import MCP_SERVER_VERSION, MCP_SPEC_VERSION +# Import version, error handling, and logging setup from common +from webex_bot_mcp.tools.common import MCP_SERVER_VERSION, MCP_SPEC_VERSION, setup_logging, log_tool_call +from webex_bot_mcp.config import get_config webex_access_token = os.getenv("WEBEX_ACCESS_TOKEN") +# Configure logging from environment before any tools run +_cfg = get_config() +setup_logging(log_level=_cfg.log_level, log_format=_cfg.log_format, debug=_cfg.debug) + class WebexAuthMiddleware(BaseHTTPMiddleware): """Enforce Bearer token auth on all MCP requests; expose /health unauthenticated.""" @@ -86,72 +91,76 @@ async def dispatch(self, request, call_next): # Initialize FastMCP with a name for the bot mcp = FastMCP("Webex Bot MCP") -# Register all tools with FastMCP +# Register all tools with FastMCP (wrapped with request/response logging) +def _tool(func): + mcp.tool()(log_tool_call(func)) + + # Room management tools -mcp.tool()(list_webex_rooms) -mcp.tool()(create_webex_room) -mcp.tool()(update_webex_room) -mcp.tool()(get_webex_room) -mcp.tool()(delete_webex_room) +_tool(list_webex_rooms) +_tool(create_webex_room) +_tool(update_webex_room) +_tool(get_webex_room) +_tool(delete_webex_room) # Space aliases (same functionality as rooms but with "space" terminology) -mcp.tool()(list_webex_spaces) -mcp.tool()(create_webex_space) -mcp.tool()(update_webex_space) -mcp.tool()(get_webex_space) -mcp.tool()(delete_webex_space) +_tool(list_webex_spaces) +_tool(create_webex_space) +_tool(update_webex_space) +_tool(get_webex_space) +_tool(delete_webex_space) # Message management tools -mcp.tool()(send_webex_message) -mcp.tool()(send_webex_message_with_mentions) -mcp.tool()(list_webex_messages) -mcp.tool()(delete_webex_message) -mcp.tool()(update_webex_message) -mcp.tool()(get_webex_attachment_action) +_tool(send_webex_message) +_tool(send_webex_message_with_mentions) +_tool(list_webex_messages) +_tool(delete_webex_message) +_tool(update_webex_message) +_tool(get_webex_attachment_action) # Space message aliases -mcp.tool()(send_webex_space_message) -mcp.tool()(list_webex_space_messages) +_tool(send_webex_space_message) +_tool(list_webex_space_messages) # Adaptive card tools -mcp.tool()(send_webex_adaptive_card) -mcp.tool()(send_webex_space_adaptive_card) -mcp.tool()(build_webex_adaptive_card) +_tool(send_webex_adaptive_card) +_tool(send_webex_space_adaptive_card) +_tool(build_webex_adaptive_card) # Membership management tools -mcp.tool()(list_webex_memberships) -mcp.tool()(add_webex_membership) -mcp.tool()(update_webex_membership) -mcp.tool()(delete_webex_membership) +_tool(list_webex_memberships) +_tool(add_webex_membership) +_tool(update_webex_membership) +_tool(delete_webex_membership) # Space membership aliases -mcp.tool()(list_webex_space_memberships) -mcp.tool()(add_webex_space_membership) +_tool(list_webex_space_memberships) +_tool(add_webex_space_membership) # People management tools -mcp.tool()(get_webex_me) -mcp.tool()(list_webex_people) +_tool(get_webex_me) +_tool(list_webex_people) # Team management tools -mcp.tool()(list_webex_teams) -mcp.tool()(get_webex_team) -mcp.tool()(update_webex_team) -mcp.tool()(delete_webex_team) +_tool(list_webex_teams) +_tool(get_webex_team) +_tool(update_webex_team) +_tool(delete_webex_team) # Team membership tools -mcp.tool()(list_webex_team_memberships) -mcp.tool()(add_webex_team_membership) -mcp.tool()(delete_webex_team_membership) +_tool(list_webex_team_memberships) +_tool(add_webex_team_membership) +_tool(delete_webex_team_membership) # Diagnostic tools -mcp.tool()(webex_health_check) +_tool(webex_health_check) # Webhook management tools -mcp.tool()(list_webex_webhooks) -mcp.tool()(create_webex_webhook) -mcp.tool()(get_webex_webhook) -mcp.tool()(update_webex_webhook) -mcp.tool()(delete_webex_webhook) +_tool(list_webex_webhooks) +_tool(create_webex_webhook) +_tool(get_webex_webhook) +_tool(update_webex_webhook) +_tool(delete_webex_webhook) # ========== RESOURCES ========== diff --git a/src/webex_bot_mcp/tools/common.py b/src/webex_bot_mcp/tools/common.py index e3fdafb..10d352e 100644 --- a/src/webex_bot_mcp/tools/common.py +++ b/src/webex_bot_mcp/tools/common.py @@ -1,10 +1,14 @@ """ Common utilities and shared components for Webex Bot MCP tools. """ +import functools +import json as _json +import logging import os +import time from datetime import datetime, timezone from functools import lru_cache -from typing import Dict, Any +from typing import Any, Callable, Dict from importlib.metadata import version, PackageNotFoundError from webexpythonsdk import WebexAPI @@ -15,6 +19,114 @@ MCP_SERVER_VERSION = "unknown" MCP_SPEC_VERSION = "2024-11-05" +# --------------------------------------------------------------------------- +# Structured logging +# --------------------------------------------------------------------------- + +logger = logging.getLogger("webex_bot_mcp") + +# kwargs that carry entity IDs worth surfacing in every log line +_TOOL_ID_PARAMS = frozenset({ + "room_id", "space_id", "team_id", "person_id", + "person_email", "membership_id", "message_id", "webhook_id", +}) + +# LogRecord fields that belong to the logging framework, not our payload +_LOG_RECORD_BUILTINS = frozenset(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) + + +class _JsonFormatter(logging.Formatter): + """Emit each log record as a single-line JSON object.""" + + def format(self, record: logging.LogRecord) -> str: + data: Dict[str, Any] = { + "timestamp": self.formatTime(record, datefmt="%Y-%m-%dT%H:%M:%S"), + "level": record.levelname, + "message": record.getMessage(), + } + for key, value in record.__dict__.items(): + if key not in _LOG_RECORD_BUILTINS and key not in ("message", "asctime"): + data[key] = value + if record.exc_info: + data["exc_info"] = self.formatException(record.exc_info) + return _json.dumps(data) + + +def setup_logging(log_level: str = "INFO", log_format: str = "text", debug: bool = False) -> None: + """Configure the webex_bot_mcp logger. + + When debug is True (WEBEX_DEBUG=true) the level is forced to DEBUG so that + tool request/response traces are emitted. Otherwise log_level is used. + Calling this a second time is a no-op (handlers already attached). + """ + log = logging.getLogger("webex_bot_mcp") + + if log.handlers: + return # already configured + + effective_level = logging.DEBUG if debug else getattr(logging, log_level.upper(), logging.INFO) + log.setLevel(effective_level) + log.propagate = False + + handler = logging.StreamHandler() + if log_format == "json": + handler.setFormatter(_JsonFormatter()) + else: + handler.setFormatter(logging.Formatter( + "%(asctime)s %(levelname)-8s %(name)s %(message)s", + datefmt="%Y-%m-%dT%H:%M:%S", + )) + log.addHandler(handler) + + +def _kv(event: str, fields: Dict[str, Any]) -> str: + """Render event + fields as 'event key=value …' for human-readable logs.""" + parts = [event] + for k, v in fields.items(): + parts.append(f"{k}={v!r}" if isinstance(v, str) else f"{k}={v}") + return " ".join(parts) + + +def log_tool_call(func: Callable) -> Callable: + """Decorator that emits structured request/response log lines for a tool. + + Fields logged on every call: tool, any entity ID kwargs present (room_id, + space_id, …), latency_ms, status, and error_code on failure. + + Request/success lines are emitted at DEBUG (visible only when + WEBEX_DEBUG=true). Error lines are emitted at WARNING so they surface in + production logs regardless of debug mode. + """ + @functools.wraps(func) + def wrapper(*args: Any, **kwargs: Any) -> Any: + tool_name = func.__name__ + start = time.monotonic() + + ctx: Dict[str, Any] = {"tool": tool_name} + for param in _TOOL_ID_PARAMS: + val = kwargs.get(param) + if val: + ctx[param] = val + + logger.debug(_kv("tool_request", ctx), extra=ctx) + + result = func(*args, **kwargs) + + ctx["latency_ms"] = round((time.monotonic() - start) * 1000, 2) + + if isinstance(result, dict) and not result.get("success"): + ctx["status"] = "error" + ctx["error_code"] = result.get("error_code", "unknown") + ctx["error_message"] = result.get("message", "") + logger.warning(_kv("tool_response", ctx), extra=ctx) + else: + ctx["status"] = "success" + logger.debug(_kv("tool_response", ctx), extra=ctx) + + return result + + return wrapper + # Error codes for structured error handling class WebexErrorCodes: """Standard error codes for Webex MCP operations.""" diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..db2c2bb --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,280 @@ +""" +Unit tests for structured logging: setup_logging() and log_tool_call(). +""" +import json +import logging +import sys +import unittest +from unittest.mock import MagicMock + +# Stub out webexpythonsdk so common.py can be imported without the real SDK +_sdk_stub = MagicMock() +sys.modules.setdefault("webexpythonsdk", _sdk_stub) +sys.modules.setdefault("webexpythonsdk.exceptions", _sdk_stub) + +from webex_bot_mcp.tools.common import ( # noqa: E402 + _JsonFormatter, + _kv, + create_error_response, + create_success_response, + log_tool_call, + setup_logging, + WebexErrorCodes, +) + + +# --------------------------------------------------------------------------- +# Helper: a simple in-memory log handler +# --------------------------------------------------------------------------- +class _Collector(logging.Handler): + def __init__(self): + super().__init__() + self.records: list[logging.LogRecord] = [] + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + + +def _fresh_logger() -> logging.Logger: + """Return the webex_bot_mcp logger with all handlers cleared.""" + log = logging.getLogger("webex_bot_mcp") + log.handlers.clear() + log.setLevel(logging.DEBUG) + log.propagate = False + return log + + +# --------------------------------------------------------------------------- +# Tests: setup_logging +# --------------------------------------------------------------------------- +class TestSetupLogging(unittest.TestCase): + + def tearDown(self): + _fresh_logger() # leave the logger clean for other test suites + + def test_debug_mode_sets_level_to_debug(self): + log = _fresh_logger() + setup_logging(log_level="INFO", log_format="text", debug=True) + self.assertEqual(log.level, logging.DEBUG) + + def test_non_debug_uses_log_level(self): + log = _fresh_logger() + setup_logging(log_level="WARNING", log_format="text", debug=False) + self.assertEqual(log.level, logging.WARNING) + + def test_idempotent_second_call_is_noop(self): + log = _fresh_logger() + setup_logging(log_level="INFO", log_format="text", debug=False) + handler_count = len(log.handlers) + setup_logging(log_level="DEBUG", log_format="json", debug=True) + # second call must not attach more handlers or change the level + self.assertEqual(len(log.handlers), handler_count) + self.assertEqual(log.level, logging.INFO) + + def test_json_format_attaches_json_formatter(self): + log = _fresh_logger() + setup_logging(log_level="INFO", log_format="json", debug=False) + self.assertIsInstance(log.handlers[0].formatter, _JsonFormatter) + + def test_text_format_attaches_standard_formatter(self): + log = _fresh_logger() + setup_logging(log_level="INFO", log_format="text", debug=False) + self.assertNotIsInstance(log.handlers[0].formatter, _JsonFormatter) + + +# --------------------------------------------------------------------------- +# Tests: _JsonFormatter +# --------------------------------------------------------------------------- +class TestJsonFormatter(unittest.TestCase): + + def _make_record(self, msg: str, extra: dict) -> logging.LogRecord: + record = logging.LogRecord( + name="webex_bot_mcp", + level=logging.DEBUG, + pathname="", + lineno=0, + msg=msg, + args=(), + exc_info=None, + ) + for k, v in extra.items(): + setattr(record, k, v) + return record + + def test_output_is_valid_json(self): + fmt = _JsonFormatter() + record = self._make_record("hello", {"tool": "send_webex_message"}) + data = json.loads(fmt.format(record)) + self.assertEqual(data["message"], "hello") + self.assertEqual(data["level"], "DEBUG") + + def test_extra_fields_included(self): + fmt = _JsonFormatter() + record = self._make_record("x", {"room_id": "abc123", "latency_ms": 42.1}) + data = json.loads(fmt.format(record)) + self.assertEqual(data["room_id"], "abc123") + self.assertEqual(data["latency_ms"], 42.1) + + def test_timestamp_field_present(self): + fmt = _JsonFormatter() + record = self._make_record("ts", {}) + data = json.loads(fmt.format(record)) + self.assertIn("timestamp", data) + + +# --------------------------------------------------------------------------- +# Tests: _kv helper +# --------------------------------------------------------------------------- +class TestKvHelper(unittest.TestCase): + + def test_event_name_is_first_token(self): + result = _kv("tool_request", {"tool": "list_rooms"}) + self.assertTrue(result.startswith("tool_request")) + + def test_string_values_are_repr_quoted(self): + result = _kv("tool_request", {"tool": "list_rooms", "room_id": "abc"}) + self.assertIn("tool='list_rooms'", result) + self.assertIn("room_id='abc'", result) + + def test_numeric_values_not_quoted(self): + result = _kv("tool_response", {"latency_ms": 12.5}) + self.assertIn("latency_ms=12.5", result) + + +# --------------------------------------------------------------------------- +# Tests: log_tool_call decorator +# --------------------------------------------------------------------------- +class TestLogToolCall(unittest.TestCase): + + def _instrument(self, func): + """Wrap func with log_tool_call and wire up a collecting handler.""" + collector = _Collector() + log = _fresh_logger() + log.addHandler(collector) + return log_tool_call(func), collector.records + + def tearDown(self): + _fresh_logger() + + # -- Return-value passthrough -- + + def test_success_return_value_preserved(self): + def my_tool(room_id=None): + return create_success_response({"id": "r1"}) + + wrapped, _ = self._instrument(my_tool) + result = wrapped(room_id="r1") + self.assertTrue(result["success"]) + self.assertEqual(result["data"]["id"], "r1") + + def test_error_return_value_preserved(self): + def my_tool(): + return create_error_response(WebexErrorCodes.NOT_FOUND, "not found") + + wrapped, _ = self._instrument(my_tool) + result = wrapped() + self.assertFalse(result["success"]) + self.assertEqual(result["error_code"], "E404") + + # -- Log emission -- + + def test_success_emits_two_debug_records(self): + def my_tool(room_id=None): + return create_success_response({}) + + wrapped, records = self._instrument(my_tool) + wrapped(room_id="abc") + debug_records = [r for r in records if r.levelno == logging.DEBUG] + self.assertEqual(len(debug_records), 2) + msgs = [r.getMessage() for r in debug_records] + self.assertTrue(any("tool_request" in m for m in msgs)) + self.assertTrue(any("tool_response" in m for m in msgs)) + + def test_error_emits_warning_record(self): + def my_tool(): + return create_error_response(WebexErrorCodes.INTERNAL_ERROR, "oops") + + wrapped, records = self._instrument(my_tool) + wrapped() + warning_records = [r for r in records if r.levelno == logging.WARNING] + self.assertEqual(len(warning_records), 1) + self.assertIn("E500", warning_records[0].getMessage()) + + # -- Structured fields -- + + def test_room_id_captured_in_record(self): + def my_tool(room_id=None): + return create_success_response({}) + + wrapped, records = self._instrument(my_tool) + wrapped(room_id="ROOM_XYZ") + response_rec = next(r for r in records if "tool_response" in r.getMessage()) + self.assertEqual(response_rec.__dict__.get("room_id"), "ROOM_XYZ") + + def test_latency_ms_present_and_is_float(self): + def my_tool(): + return create_success_response({}) + + wrapped, records = self._instrument(my_tool) + wrapped() + response_rec = next(r for r in records if "tool_response" in r.getMessage()) + self.assertIn("latency_ms", response_rec.__dict__) + self.assertIsInstance(response_rec.__dict__["latency_ms"], float) + + def test_error_code_in_warning_record_extra(self): + def my_tool(): + return create_error_response(WebexErrorCodes.RATE_LIMITED, "slow down") + + wrapped, records = self._instrument(my_tool) + wrapped() + warning = next(r for r in records if r.levelno == logging.WARNING) + self.assertEqual(warning.__dict__.get("error_code"), "E503") + + def test_tool_name_in_request_record(self): + def list_webex_rooms(): + return create_success_response({}) + + wrapped, records = self._instrument(list_webex_rooms) + wrapped() + request_rec = next(r for r in records if "tool_request" in r.getMessage()) + self.assertEqual(request_rec.__dict__.get("tool"), "list_webex_rooms") + + def test_status_success_in_response_record(self): + def my_tool(): + return create_success_response({}) + + wrapped, records = self._instrument(my_tool) + wrapped() + response_rec = next(r for r in records if "tool_response" in r.getMessage()) + self.assertEqual(response_rec.__dict__.get("status"), "success") + + def test_status_error_in_response_record(self): + def my_tool(): + return create_error_response(WebexErrorCodes.FORBIDDEN, "no access") + + wrapped, records = self._instrument(my_tool) + wrapped() + response_rec = next(r for r in records if "tool_response" in r.getMessage()) + self.assertEqual(response_rec.__dict__.get("status"), "error") + + # -- functools.wraps metadata -- + + def test_wraps_preserves_name_and_docstring(self): + def my_special_tool(room_id: str = None) -> dict: + """My special tool docstring.""" + return {} + + wrapped = log_tool_call(my_special_tool) + self.assertEqual(wrapped.__name__, "my_special_tool") + self.assertEqual(wrapped.__doc__, "My special tool docstring.") + + def test_wraps_sets_wrapped_attribute(self): + def my_tool(): + return {} + + wrapped = log_tool_call(my_tool) + self.assertIs(wrapped.__wrapped__, my_tool) + + +if __name__ == "__main__": + unittest.main()