ask262/.opencode/plans/1776768885483-glowing-panda.md

---
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