From 5d7c8c0068851477d04b2cf61fb80aa6e54eddc8 Mon Sep 17 00:00:00 2001 From: bendtherules Date: Tue, 21 Apr 2026 17:39:47 +0530 Subject: [PATCH] plan(logging): structured logging for MCP server with OpenTelemetry and Pino --- .../plans/1776768885483-glowing-panda.md | 434 ++++++++++++++++++ 1 file changed, 434 insertions(+) create mode 100644 .opencode/plans/1776768885483-glowing-panda.md diff --git a/.opencode/plans/1776768885483-glowing-panda.md b/.opencode/plans/1776768885483-glowing-panda.md new file mode 100644 index 0000000..395e920 --- /dev/null +++ b/.opencode/plans/1776768885483-glowing-panda.md @@ -0,0 +1,434 @@ +--- +model: accounts/fireworks/routers/kimi-k2p5-turbo +title: Add Proper Server Logs for MCP Server +--- + +# Plan: Add Proper Server Logs for Ask262 MCP Server + +## Overview +Implement structured logging with OpenTelemetry-style tracing for both stdio and HTTP MCP servers, using Pino + @opentelemetry/api + pino-roll, writing JSON Lines to file, with DuckDB for querying. + +## Goals +- Trace nested calls (parent-child span relationships) +- Log all operations with timing information +- Structured format for external consumption +- Zero runtime dependencies for querying (DuckDB is CLI-only) +- Minimal footprint architecture + +## Architecture + +``` +┌─────────────────────────────────────┐ +│ Pino + @opentelemetry/api │ +│ ↓ │ +│ JSON Lines → ./logs/ask262.jsonl │ +│ ↓ │ +│ DuckDB CLI (query when needed) │ +└─────────────────────────────────────┘ +``` + +## Configuration + +| Variable | Default | Description | +|----------|---------|-------------| +| `ASK262_LOG_LEVEL` | `debug` (HTTP), `info` (stdio) | File log level: trace/debug/info/warn/error | +| `ASK262_LOG_DIR` | `./logs` | Log directory path | +| `ASK262_LOG_MAX_SIZE` | `100` | Rotation threshold in MB | + +Console level is calculated as `max('info', ASK262_LOG_LEVEL)` - never shows debug, follows ASK262_LOG_LEVEL if higher. + +**Transport-aware defaults:** +- HTTP server: `ASK262_LOG_LEVEL=debug` (verbose, includes all operations) +- Stdio server: `ASK262_LOG_LEVEL=info` (standard, shows operations but not debug details) + +## File Structure + +- **Format**: JSON Lines (one JSON object per line) +- **Path**: `${ASK262_LOG_DIR}/ask262.jsonl` +- **Rotation**: By system logrotate (100MB, managed by Coolify cron) +- **Rotated files**: `ask262.jsonl.1`, `ask262.jsonl.2`, etc. (numbered, not timestamped) +- **Retention**: Delete old files via Coolify cron (30 days) +- **Permissions**: Default (0o644) +- **Sync**: Synchronous writes (guaranteed durability) + +## Log Schema + +| Field | Type | Description | +|-------|------|-------------| +| `timestamp` | ISO8601 | With milliseconds | +| `level` | number | 10=trace, 20=debug, 30=info, 40=warn, 50=error | +| `trace_id` | string | Request correlation ID | +| `span_id` | string | Unique operation ID | +| `parent_span_id` | string\|null | Parent operation ID | +| `component` | string | `http-server`, `stdio-server`, `search-tool`, `get-section-tool`, `engine262-runner`, `reranker`, `graph-explorer` | +| `operation` | string | `mcp_request`, `vector_search`, `section_fetch`, `code_execution`, `embedding_generate` | +| `duration_ms` | number\|null | Operation duration | +| `msg` | string | Human-readable message | +| `client_ip` | string\|null | Request IP (HTTP only) | +| `attributes` | object | Key=value metadata | +| `err` | object\|null | Error details with stack trace | + +## Components + +### Trace ID Strategy + +- **HTTP**: Generate new UUID per request (from header if available) +- **Stdio**: One process-scoped trace_id for entire session + +### Logger API + +```typescript +// Get component logger +const log = logger.forComponent('search-tool'); + +// Simple log +log.info('operation_started', { query: 'how does array.map work' }); + +// Timed operation (auto duration) +const op = log.start('vector_search', { query: 'how does array.map work' }); +const results = await doSearch(query); +op.end({ results: results.length, provider: 'fireworks' }); +// Logs on end with duration_ms automatically calculated +``` + +## Dependencies + +```json +{ + "pino": "^8.x", + "@opentelemetry/api": "^1.x" + // pino-roll removed - using system logrotate via Coolify cron +} +``` + +**Coolify/System Requirements:** +- `logrotate` installed in container (standard in most Linux images) + +## Files to Create + +### 1. `coolify.yaml` +Coolify deployment configuration with log rotation and cleanup cron jobs. + +```yaml +# coolify.yaml - Coolify deployment configuration +version: 1 + +services: + - name: ask262 + +cronjobs: + - name: "log-rotation" + schedule: "*/5 * * * *" # Every 5 minutes + command: "logrotate -f /app/logrotate.conf 2>/dev/null || true" + + - name: "log-cleanup" + schedule: "0 0 * * *" # Daily at midnight + command: "find ${ASK262_LOG_DIR:-/app/logs} -name 'ask262.jsonl.*' -mtime +${ASK262_LOG_RETENTION_DAYS:-30} -delete 2>/dev/null || true" +``` + +### 2. `logrotate.conf` +Log rotation configuration for system logrotate. + +```bash +${ASK262_LOG_DIR}/ask262.jsonl { + size 100M + rotate 10 + compress + delaycompress + copytruncate + notifempty + missingok +} +``` + +### 3. `src/lib/logger.ts` +Central logging module with component binding and auto-duration operations. + +**Key features:** +- Component-bound loggers: `const log = logger.forComponent('search-tool')` +- Timed operations: `const op = log.start('vector_search', attrs); op.end(resultAttrs)` +- Automatic trace context injection via @opentelemetry/api +- Dual transport: JSON Lines to file, pretty to console (filtered) +- Redaction of sensitive fields + +**Pino configuration:** +```typescript +const logger = pino({ + level: getFileLogLevel(), // From ASK262_LOG_LEVEL env + redact: { + paths: ['FIREWORKS_API_KEY', 'api_key', 'authorization'], + remove: true + }, + mixin() { + const span = trace.getSpan(context.active()); + if (span) { + const ctx = span.spanContext(); + return { + trace_id: ctx.traceId, + span_id: ctx.spanId, + trace_flags: ctx.traceFlags, + }; + } + return {}; + }, + timestamp: () => `,"timestamp":"${new Date().toISOString()}"`, +}, pino.multistream([ + // File: JSON, all levels per ASK262_LOG_LEVEL (no rotation here - system handles it) + { + stream: pino.destination({ + dest: join(ASK262_LOG_DIR, 'ask262.jsonl'), + sync: true // Synchronous writes + }), + level: getFileLogLevel() + }, + // Console: Pretty, filtered to max('info', ASK262_LOG_LEVEL) + { + stream: pretty({ colorize: true }), + level: getConsoleLogLevel() // max('info', ASK262_LOG_LEVEL) + } +])); +``` + +### 4. `src/lib/tracing.ts` +OpenTelemetry trace context management using AsyncLocalStorage. + +**Key features:** +- `createTraceContext(traceId?: string)` - Initialize trace at entry point +- `withSpan(operation, attributes, fn)` - Wrap operations with automatic parent-child linking +- Uses @opentelemetry/api for context propagation +- Automatic span ID generation + +## Files to Modify + +### 5. `src/mcp-server-http.ts` +**Changes:** +- Import logger and tracing modules +- Create trace context at request entry point +- Extract client IP from request headers +- Add startup/shutdown logs (minimal) +- Add logging around tool invocations + +```typescript +// Startup +log.info('server_started', { port: ASK262_PORT, transport: 'http' }); + +// Per request +const traceId = req.headers['x-request-id'] || crypto.randomUUID(); +await withSpan('mcp_request', { tool: toolName, client_ip: clientIp }, async () => { + const log = logger.forComponent('http-server'); + const op = log.start('handle_request', { tool: toolName }); + const result = await toolHandler(args); + op.end({ status: 'success', result_count: result.length }); + return result; +}); + +// Shutdown +log.info('server_shutting_down', { signal: 'SIGTERM' }); +``` + +### 6. `src/mcp-server-stdio.ts` +**Changes:** +- Import logger and tracing modules +- Create process-scoped trace_id on startup +- Add startup/shutdown logs (minimal) +- Add logging matching HTTP server pattern (no IP) + +```typescript +// Startup - one trace_id for entire session +const sessionTraceId = crypto.randomUUID(); +log.info('server_started', { transport: 'stdio', trace_id: sessionTraceId }); + +// Per message - uses same trace_id via AsyncLocalStorage +await withSpan('mcp_request', { tool: toolName }, async () => { + // Same pattern as HTTP +}); +``` + +### 7. `src/agent-tools/searchSpecSections.ts` +**Changes:** +- Import component logger +- Add operation spans for: + - Vector search query + - Embedding generation (if cached vs fresh) + - Reranking (if enabled) + - Result formatting +- Log query parameters, result counts, timing +- Log errors with full context + +### 8. `src/agent-tools/getSectionContent.ts` +**Changes:** +- Add logging for section lookup +- Log section IDs found/not found +- Log content size +- Log timing for LanceDB queries + +### 9. `src/agent-tools/evaluateInEngine262.ts` + `runner` +**Changes:** +- Add parent-child span tracking across process boundary +- Pass trace context to runner via env or message +- Log code execution request +- Runner logs as child spans +- Log execution time +- Log errors with stack traces + +### 10. `src/agent-tools/graphExplorer.ts` +**Changes:** +- Log graph traversal operations +- Log node/edge counts +- Log query timing + +### 11. `src/agent-tools/reranker.ts` +**Changes:** +- Log reranking requests +- Log API success/failure +- Log timing + +### 12. `src/lib/embeddings-factory.ts` +**Changes:** +- Log provider selection +- Log embedding generation batches +- Log errors with provider context + +### 13. `src/lib/fireworks-embeddings.ts` +**Changes:** +- Log rate limit retries +- Log API timing +- Log batch sizes + +### 14. `.env.example` +**Add:** +```bash +# Logging configuration +# HTTP server defaults to 'debug', stdio defaults to 'info' +ASK262_LOG_LEVEL=info # trace, debug, info, warn, error +ASK262_LOG_DIR=./logs # Log file directory +ASK262_LOG_MAX_SIZE=100 # Max file size in MB before rotation +ASK262_LOG_RETENTION_DAYS=30 # Days to keep rotated logs (0=keep forever) +``` + +### 15. `.gitignore` +**Add:** +``` +# Logs +/logs/ +*.log +*.jsonl +``` + +## DuckDB Query Examples + +### Installation +```bash +brew install duckdb # macOS +# or download from https://duckdb.org/ +``` + +### Common Queries +```sql +-- View all logs for a trace +SELECT timestamp, component, operation, duration_ms, msg +FROM 'logs/ask262.jsonl' +WHERE trace_id = '4bf92f3577b34da6a3ce929d0e0e4736' +ORDER BY time; + +-- Find slow operations +SELECT component, operation, + AVG(duration_ms) as avg_ms, + MAX(duration_ms) as max_ms, + COUNT(*) as count +FROM 'logs/ask262.jsonl' +WHERE duration_ms IS NOT NULL +GROUP BY component, operation +ORDER BY avg_ms DESC; + +-- Error analysis +SELECT component, operation, COUNT(*) as errors +FROM 'logs/ask262.jsonl' +WHERE level >= 40 +GROUP BY component, operation; + +-- Request volume over time +SELECT date_trunc('hour', timestamp::TIMESTAMP) as hour, + COUNT(*) as requests +FROM 'logs/ask262.jsonl' +WHERE component = 'http-server' AND operation = 'mcp_request' +GROUP BY hour +ORDER BY hour; + +-- Trace duration (time from first to last span) +SELECT trace_id, + MIN(timestamp) as start_time, + MAX(timestamp) as end_time, + MAX(timestamp)::TIMESTAMP - MIN(timestamp)::TIMESTAMP as total_duration +FROM 'logs/ask262.jsonl' +WHERE trace_id IS NOT NULL +GROUP BY trace_id +ORDER BY total_duration DESC +LIMIT 10; +``` + +## Implementation Order + +1. **Coolify config** (`coolify.yaml`, `logrotate.conf`) - Deployment and rotation setup +2. **Core logger** (`src/lib/logger.ts`) - Pino setup, transports, redaction +3. **Tracing module** (`src/lib/tracing.ts`) - OTel context, span management +4. **HTTP server** (`src/mcp-server-http.ts`) - Entry point, test end-to-end +5. **Stdio server** (`src/mcp-server-stdio.ts`) - Same pattern as HTTP +6. **Agent tools** - searchSpecSections, getSectionContent, evaluateInEngine262, graphExplorer, reranker +7. **Library files** - embeddings-factory, fireworks-embeddings +8. **Documentation** - .env.example, .gitignore +9. **Testing** - Verify all components log correctly + +## Testing Plan + +1. **Unit tests**: Verify logger creates correct JSON structure +2. **Integration tests**: + - Make MCP requests, verify logs created + - Check trace_id consistency across nested calls + - Verify span parent-child relationships +3. **Manual verification**: + - Query logs with DuckDB + - Verify timing calculations + - Check error logging includes stack traces + - Test log rotation at 100MB + - Verify console pretty output + +## Verification Steps + +After implementation: + +1. Install dependencies: `bun add pino @opentelemetry/api pino-roll` +2. Run HTTP server: `bun run ask262-http` +3. Check logs directory created: `ls -la logs/` +4. Make test request via MCP Inspector or curl +5. Query with DuckDB: `duckdb -c "SELECT * FROM 'logs/ask262.jsonl' LIMIT 5"` +6. Check console output is pretty-printed +7. Run stdio server: `bun run ask262-stdio` +8. Send MCP message via stdin +9. Verify both servers produce consistent log format +10. Test rotation: Send many requests, verify rotation at 100MB +11. Test error logging: Trigger error, verify stack trace in logs + +## Error Handling + +**Log directory unwritable:** Server crashes on startup with clear error message. + +**Log rotation fails:** Continue with current file, log warning (don't crash on rotation failure). + +**Disk full:** Synchronous writes will fail, error propagated up and logged to console. + +## Success Criteria + +- [ ] All tool operations logged with timing +- [ ] Nested calls have trace_id and parent_span_id relationships +- [ ] HTTP server logs include client IP +- [ ] Stdio server has process-scoped trace_id +- [ ] Console shows pretty output, filtered to appropriate level +- [ ] File has JSON Lines format +- [ ] DuckDB can query logs without errors +- [ ] Log rotation works at 100MB with timestamp suffix +- [ ] Error logs include full context and stack traces +- [ ] API keys redacted from all logs +- [ ] No impact on MCP protocol communication +- [ ] Server crashes if log directory unwritable +- [ ] Minimal startup/shutdown logs present