feat(mcp): add observability decorators for automatic tool instrumentation (#172)

* feat(mcp): add @observe_tool and @observe_service decorators with tests

* feat(mcp): apply @observe_tool decorator to all foundation tools

* docs(mcp): add comprehensive documentation for observability decorators to LOGGING.md

Author: Copilot

katana_mcp_server/docs/LOGGING.md

@@ -1,14 +1,19 @@
 # Structured Logging in Katana MCP Server
 
-The Katana MCP Server uses structured logging with [structlog](https://www.structlog.org/) to provide rich observability and debugging capabilities.
+The Katana MCP Server uses structured logging with
+[structlog](https://www.structlog.org/) to provide rich observability and debugging
+capabilities.
 
 ## Features
 
-- **Structured JSON or text output** - Choose between JSON (for log aggregation) or human-readable text format
-- **Contextual information** - Every log includes relevant context (tool names, SKUs, IDs, etc.)
+- **Structured JSON or text output** - Choose between JSON (for log aggregation) or
+  human-readable text format
+- **Contextual information** - Every log includes relevant context (tool names, SKUs,
+  IDs, etc.)
 - **Performance metrics** - Automatic duration tracking for all tool executions
 - **Trace IDs** - Support for request correlation across operations
-- **Security** - Automatic redaction of sensitive data (API keys, passwords, credentials)
+- **Security** - Automatic redaction of sensitive data (API keys, passwords,
+  credentials)
 - **Configurable levels** - Control log verbosity via environment variables
 
 ## Configuration
@@ -18,21 +23,25 @@ The Katana MCP Server uses structured logging with [structlog](https://www.struc
 Configure logging behavior with these environment variables:
 
 - **`KATANA_MCP_LOG_LEVEL`** - Log level (default: `INFO`)
+
   - Options: `DEBUG`, `INFO`, `WARNING`, `ERROR`
-  
+
 - **`KATANA_MCP_LOG_FORMAT`** - Output format (default: `json`)
+
   - Options: `json`, `text`
 
 ### Examples
 
 **Development (verbose text output):**
+
 ```bash
 export KATANA_MCP_LOG_LEVEL=DEBUG
 export KATANA_MCP_LOG_FORMAT=text
 katana-mcp-server
 ```
 
 **Production (structured JSON):**
+
 ```bash
 export KATANA_MCP_LOG_LEVEL=INFO
 export KATANA_MCP_LOG_FORMAT=json
@@ -66,6 +75,7 @@ katana-mcp-server
 ### Server Lifecycle
 
 **Server Initialization:**
+
 ```json
 {
   "event": "server_initializing",
@@ -76,6 +86,7 @@ katana-mcp-server
 ```
 
 **Client Ready:**
+
 ```json
 {
   "event": "client_initialized",
@@ -87,6 +98,7 @@ katana-mcp-server
 ```
 
 **Server Ready:**
+
 ```json
 {
   "event": "server_ready",
@@ -98,6 +110,7 @@ katana-mcp-server
 ### Tool Execution
 
 **Inventory Check (Success):**
+
 ```json
 {
   "event": "inventory_check_completed",
@@ -111,6 +124,7 @@ katana-mcp-server
 ```
 
 **Search Items (Success):**
+
 ```json
 {
   "event": "item_search_completed",
@@ -122,6 +136,7 @@ katana-mcp-server
 ```
 
 **Create Item (Success):**
+
 ```json
 {
   "event": "item_create_completed",
@@ -137,6 +152,7 @@ katana-mcp-server
 ### Error Logging
 
 **Tool Failure:**
+
 ```json
 {
   "event": "item_search_failed",
@@ -150,6 +166,7 @@ katana-mcp-server
 ```
 
 **Authentication Error:**
+
 ```json
 {
   "event": "authentication_failed",
@@ -166,11 +183,13 @@ katana-mcp-server
 The logger automatically redacts sensitive information from logs:
 
 **Input:**
+
 ```python
 logger.info("api_call", api_key="secret-key-123", username="john")
 ```
 
 **Output (JSON):**
+
 ```json
 {
   "event": "api_call",
@@ -181,6 +200,7 @@ logger.info("api_call", api_key="secret-key-123", username="john")
 ```
 
 **Redacted Keys:**
+
 - `api_key`, `API_KEY`
 - `password`, `PASSWORD`
 - `secret`, `SECRET`
@@ -199,6 +219,7 @@ All tool executions include performance metrics:
 - **`threshold`** - Configured threshold (for low stock checks)
 
 Example with metrics:
+
 ```json
 {
   "event": "low_stock_search_completed",
@@ -210,14 +231,238 @@ Example with metrics:
 }
 ```
 
+## Observability Decorators
+
+The Katana MCP Server provides convenience decorators to automatically instrument tools
+and service methods with logging, timing, and error tracking.
+
+### @observe_tool
+
+Automatically instruments MCP tool functions with comprehensive observability.
+
+**Features:**
+
+- Automatic logging of tool invocations with parameters
+- Execution timing in milliseconds
+- Success/failure tracking
+- Error details with exception types
+- Context parameter filtering (ctx/context excluded from logs)
+
+**Usage:**
+
+```python
+from katana_mcp.logging import observe_tool
+from fastmcp import Context
+
+@observe_tool
+@mcp.tool()
+async def my_tool(request: MyRequest, context: Context) -> MyResponse:
+    """My tool implementation."""
+    return await do_work()
+```
+
+**Log Events Produced:**
+
+Tool invocation (INFO level):
+
+```json
+{
+  "event": "tool_invoked",
+  "tool_name": "my_tool",
+  "params": {"request": {...}},
+  "timestamp": "2025-01-05T17:08:40.123456Z",
+  "level": "info"
+}
+```
+
+Successful completion (INFO level):
+
+```json
+{
+  "event": "tool_completed",
+  "tool_name": "my_tool",
+  "duration_ms": 245.67,
+  "success": true,
+  "timestamp": "2025-01-05T17:08:40.369126Z",
+  "level": "info"
+}
+```
+
+Tool failure (ERROR level):
+
+```json
+{
+  "event": "tool_failed",
+  "tool_name": "my_tool",
+  "duration_ms": 12.34,
+  "error": "Invalid request parameters",
+  "error_type": "ValueError",
+  "success": false,
+  "timestamp": "2025-01-05T17:08:40.135796Z",
+  "level": "error"
+}
+```
+
+**Best Practices:**
+
+- Place `@observe_tool` before `@mcp.tool()` decorator
+- Use with `@unpack_pydantic_params` for parameter unpacking
+- Context parameters (ctx, context) are automatically filtered from logs
+- No need to add manual timing or error logging in tool implementation
+
+**Example with Parameter Unpacking:**
+
+```python
+@observe_tool
+@unpack_pydantic_params
+async def search_items(
+    request: Annotated[SearchItemsRequest, Unpack()], context: Context
+) -> SearchItemsResponse:
+    """Search for items - automatically instrumented."""
+    services = get_services(context)
+    return await services.client.variants.search(request.query)
+```
+
+### @observe_service
+
+Instruments service layer methods with debug-level logging.
+
+**Features:**
+
+- Service operation tracking
+- Method timing
+- Error logging with context
+- Class name extraction
+
+**Usage:**
+
+```python
+from katana_mcp.logging import observe_service
+
+class MyService:
+    @observe_service("get_item")
+    async def get(self, item_id: int) -> Item:
+        """Fetch item by ID."""
+        return await self._fetch(item_id)
+    
+    @observe_service("create_item")
+    async def create(self, data: dict) -> Item:
+        """Create new item."""
+        return await self._create(data)
+```
+
+**Log Events Produced:**
+
+Operation started (DEBUG level):
+
+```json
+{
+  "event": "service_operation_started",
+  "service": "MyService",
+  "operation": "get_item",
+  "params": {"item_id": 123},
+  "timestamp": "2025-01-05T17:08:40.123456Z",
+  "level": "debug"
+}
+```
+
+Operation completed (DEBUG level):
+
+```json
+{
+  "event": "service_operation_completed",
+  "service": "MyService",
+  "operation": "get_item",
+  "duration_ms": 45.67,
+  "success": true,
+  "timestamp": "2025-01-05T17:08:40.169126Z",
+  "level": "debug"
+}
+```
+
+Operation failed (ERROR level):
+
+```json
+{
+  "event": "service_operation_failed",
+  "service": "MyService",
+  "operation": "get_item",
+  "duration_ms": 12.34,
+  "error": "Item not found",
+  "error_type": "ItemNotFoundError",
+  "success": false,
+  "timestamp": "2025-01-05T17:08:40.135796Z",
+  "level": "error"
+}
+```
+
+**Best Practices:**
+
+- Use descriptive operation names (e.g., "get_product", "create_order")
+- Service operations log at DEBUG level (less verbose than tools)
+- Use for lower-level operations called by tools
+- Provides granular visibility into service layer performance
+
+### Decorator Comparison
+
+| Feature                 | @observe_tool                      | @observe_service                      |
+| ----------------------- | ---------------------------------- | ------------------------------------- |
+| **Use Case**            | MCP tools (user-facing operations) | Service methods (internal operations) |
+| **Log Level**           | INFO                               | DEBUG                                 |
+| **Parameter Filtering** | Yes (ctx/context)                  | No                                    |
+| **Primary Audience**    | Operations/users                   | Developers                            |
+| **Visibility**          | High (always logged in production) | Low (only in debug mode)              |
+
+### Migration Guide
+
+**Before (Manual Logging):**
+
+```python
+@mcp.tool()
+async def my_tool(request: MyRequest, context: Context) -> MyResponse:
+    logger.info("my_tool_started", request=request)
+    start_time = time.monotonic()
+    try:
+        result = await do_work()
+        duration_ms = (time.monotonic() - start_time) * 1000
+        logger.info("my_tool_completed", duration_ms=duration_ms)
+        return result
+    except Exception as e:
+        logger.error("my_tool_failed", error=str(e))
+        raise
+```
+
+**After (With Decorator):**
+
+```python
+@observe_tool
+@mcp.tool()
+async def my_tool(request: MyRequest, context: Context) -> MyResponse:
+    return await do_work()  # Automatic logging, timing, error tracking!
+```
+
+**Benefits:**
+
+- 10+ lines of boilerplate eliminated per tool
+- Consistent log format across all tools
+- Automatic error tracking without try/except
+- Performance metrics captured automatically
+- No risk of forgetting to log important events
+
 ## Best Practices
 
 1. **Use INFO level in production** - Provides operational visibility without noise
-2. **Use DEBUG for troubleshooting** - Includes detailed execution traces
-3. **Use JSON format for log aggregation** - Easier to parse and analyze
-4. **Use text format for development** - More human-readable
-5. **Monitor duration_ms** - Identify performance bottlenecks
-6. **Never log sensitive data** - The filter catches common patterns, but be careful with custom fields
+1. **Use DEBUG for troubleshooting** - Includes detailed execution traces and service
+   operations
+1. **Use JSON format for log aggregation** - Easier to parse and analyze
+1. **Use text format for development** - More human-readable
+1. **Monitor duration_ms** - Identify performance bottlenecks
+1. **Never log sensitive data** - The filter catches common patterns, but be careful
+   with custom fields
+1. **Use @observe_tool for all MCP tools** - Automatic instrumentation with zero
+   boilerplate
+1. **Use @observe_service for service methods** - Granular visibility into internal
+   operations
 
 ## References