mirror of
https://github.com/bendtherules/ask262.git
synced 2026-08-18 21:31:46 +00:00
plan(logging): structured logging for MCP server with OpenTelemetry and Pino
This commit is contained in:
@@ -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
|
||||
Reference in New Issue
Block a user