Merge branch 'inspector'

.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

src/agent-tools/getSectionContent.ts

@@ -20,8 +20,7 @@ const sectionDataSchema = z.object({
   found: z.boolean(),
   error: z.string().optional(),
   sectionTitle: z.string().optional(),
-  partIndex: z.number().optional(),
+  childrensectionids: z.array(z.string()).optional(),
-  totalParts: z.number().optional(),
 });
 
 const getSectionContentOutputSchema = z.object({
@@ -87,8 +86,7 @@ export function createGetSectionContentTool(table: Table) {
       {
         content: string[];
         title?: string;
-        partIndex?: number;
+        childrenSectionIds?: string[];
-        totalParts?: number;
       }
     >();
     const queue: string[] = [...sectionIds];
@@ -121,18 +119,18 @@ export function createGetSectionContentTool(table: Table) {
           totalparts?: number;
         };
 
+        // Get or create section data
+        let section = sectionsData.get(currentId);
+        if (!section) {
+          section = {
+            content: [],
+            title: typedResult.sectiontitle,
+            childrenSectionIds: typedResult.childrensectionids,
+          };
+          sectionsData.set(currentId, section);
+        }
+
         if (typedResult.text) {
-          // Get or create section data
-          let section = sectionsData.get(currentId);
-          if (!section) {
-            section = {
-              content: [],
-              title: typedResult.sectiontitle,
-              partIndex: typedResult.partindex ?? undefined,
-              totalParts: typedResult.totalparts ?? undefined,
-            };
-            sectionsData.set(currentId, section);
-          }
           section.content.push(typedResult.text);
         }
 
@@ -157,8 +155,7 @@ export function createGetSectionContentTool(table: Table) {
           content: data.content.join("\n\n"),
           found: true,
           sectionTitle: data.title,
-          partIndex: data.partIndex,
+          childrensectionids: data.childrenSectionIds,
-          totalParts: data.totalParts,
         };
       }
       return {

src/mcp-server-http.ts

@@ -284,7 +284,10 @@ export async function main() {
 
   // MCP Inspector at root path - auto-connects to /mcp
   // Mounted AFTER /mcp so specific routes take precedence
-  const mcpPublicUrl =  process.env.COOLIFY_URL || process.env.MCP_PUBLIC_URL || `http://localhost:${PORT}`;
+  const mcpPublicUrl =
+    process.env.COOLIFY_URL ||
+    process.env.MCP_PUBLIC_URL ||
+    `http://localhost:${PORT}`;
   mountInspector(app, {
     autoConnectUrl: `${mcpPublicUrl}/mcp`,
     devMode: process.env.NODE_ENV !== "production",