Skip to content

Debugging Guide

Eric Fitzgerald edited this page Nov 12, 2025 · 1 revision

Debugging Guide

This guide provides systematic procedures for debugging TMI issues including debug logging, log analysis, browser developer tools, and database queries.

Debug Logging

Enabling Debug Logging

TMI supports multiple log levels to control verbosity:

Log Levels:

  • debug - Detailed diagnostic information
  • info - General informational messages (default)
  • warn - Warning messages for potentially harmful situations
  • error - Error messages for serious problems

Enable debug logging:

# Via environment variable
export LOG_LEVEL=debug
./bin/tmiserver

# Via configuration file
echo "log_level: debug" >> config-development.yml

# Via Docker
docker run -e LOG_LEVEL=debug tmi-server

Log Output Formats

Text format (human-readable, development):

export LOG_FORMAT=text

Example output:

2025-01-15T10:30:00Z INFO  Server starting on :8080
2025-01-15T10:30:01Z DEBUG Connected to PostgreSQL host=localhost port=5432
2025-01-15T10:30:01Z DEBUG Connected to Redis host=localhost port=6379

JSON format (structured, production):

export LOG_FORMAT=json

Example output:

{"time":"2025-01-15T10:30:00Z","level":"INFO","msg":"Server starting on :8080"}
{"time":"2025-01-15T10:30:01Z","level":"DEBUG","msg":"Connected to PostgreSQL","host":"localhost","port":5432}

Component-Specific Logging

Enable debug logging for specific components:

# Authentication debugging
export LOG_LEVEL=debug
export AUTH_DEBUG=true

# Database query logging
export DB_LOG_QUERIES=true

# WebSocket debugging
export WS_DEBUG=true

# Webhook debugging
export WEBHOOK_DEBUG=true

Log File Configuration

Specify log file location:

# Write logs to file
export LOG_FILE=/var/log/tmi/server.log
./bin/tmiserver

# Or in configuration
log:
  level: debug
  format: json
  file: /var/log/tmi/server.log

Log rotation (use logrotate):

# /etc/logrotate.d/tmi
/var/log/tmi/*.log {
    daily
    rotate 7
    compress
    delaycompress
    notifempty
    create 0644 tmi tmi
    sharedscripts
    postrotate
        systemctl reload tmi
    endscript
}

Log Analysis

Reading TMI Logs

TMI uses structured logging with consistent fields:

Key fields:

  • time - Timestamp (RFC3339 format)
  • level - Log level (DEBUG, INFO, WARN, ERROR)
  • msg - Human-readable message
  • component - Component name (server, auth, database, websocket)
  • user_id - User identifier (when applicable)
  • request_id - Request trace ID
  • duration - Request/operation duration (milliseconds)

Example log entries:

{"time":"2025-01-15T10:30:00Z","level":"INFO","component":"server","msg":"HTTP request","method":"GET","path":"/api/v1/threat-models","status":200,"duration":45,"user_id":"abc-123"}
{"time":"2025-01-15T10:30:01Z","level":"ERROR","component":"database","msg":"Query failed","query":"SELECT * FROM threat_models","error":"connection refused"}
{"time":"2025-01-15T10:30:02Z","level":"DEBUG","component":"websocket","msg":"Client connected","client_id":"xyz-789"}

Filtering and Searching Logs

Search for errors:

# All errors
grep '"level":"ERROR"' logs/tmi.log

# Errors with text format
grep 'ERROR' logs/tmi.log

# Errors in last hour
grep '"level":"ERROR"' logs/tmi.log | grep "$(date -u +%Y-%m-%dT%H)"

Search by component:

# Database logs
grep '"component":"database"' logs/tmi.log

# Authentication logs
grep '"component":"auth"' logs/tmi.log

# WebSocket logs
grep '"component":"websocket"' logs/tmi.log

Search by user:

# All activity for specific user
grep '"user_id":"abc-123"' logs/tmi.log

# Failed operations for user
grep '"user_id":"abc-123"' logs/tmi.log | grep '"level":"ERROR"'

Search by request:

# Follow request through system
grep '"request_id":"req-xyz-789"' logs/tmi.log

# All GET requests
grep '"method":"GET"' logs/tmi.log

# Slow requests (>1000ms)
grep '"duration":[0-9][0-9][0-9][0-9]' logs/tmi.log

Log Analysis Tools

jq for JSON logs:

# Pretty print JSON logs
cat logs/tmi.log | jq .

# Extract error messages
cat logs/tmi.log | jq 'select(.level=="ERROR") | .msg'

# Count errors by component
cat logs/tmi.log | jq 'select(.level=="ERROR") | .component' | sort | uniq -c

# Find slowest requests
cat logs/tmi.log | jq 'select(.duration > 1000) | {path, duration}' | sort -k2 -n

grep patterns:

# Authentication failures
grep -i "authentication failed\|unauthorized\|invalid token" logs/tmi.log

# Database errors
grep -i "database error\|connection refused\|query failed" logs/tmi.log

# WebSocket issues
grep -i "websocket.*error\|connection.*closed\|upgrade failed" logs/tmi.log

# Performance issues
grep '"duration":[5-9][0-9][0-9][0-9]' logs/tmi.log  # >5 seconds

Common patterns:

# Top 10 API endpoints by count
grep '"method":"' logs/tmi.log | jq -r '.path' | sort | uniq -c | sort -rn | head -10

# Error rate per hour
grep '"level":"ERROR"' logs/tmi.log | jq -r '.time' | cut -d: -f1-2 | uniq -c

# Average request duration by endpoint
grep '"duration":' logs/tmi.log | jq '{path, duration}' | jq -s 'group_by(.path) | map({path: .[0].path, avg: (map(.duration) | add / length)})'

Browser Developer Tools

Console Debugging

Open Developer Tools:

  • Chrome/Edge: F12 or Ctrl+Shift+I (Windows/Linux), Cmd+Option+I (Mac)
  • Firefox: F12 or Ctrl+Shift+I (Windows/Linux), Cmd+Option+I (Mac)
  • Safari: Cmd+Option+I (Mac) - Enable "Show Develop menu" in Preferences first

Key areas to check:

  1. Console Tab:

    • JavaScript errors
    • Failed API calls
    • WebSocket connection issues
    • Application warnings
  2. Network Tab:

    • API request/response details
    • HTTP status codes
    • Request/response headers
    • WebSocket handshake
  3. Application Tab:

    • Local storage (JWT tokens)
    • Session storage
    • Cookies
    • Cache status

Debugging API Calls

Network tab inspection:

  1. Open Network tab in Developer Tools
  2. Refresh page or trigger API call
  3. Find request in list
  4. Click to view details:
    • Headers: Request/response headers, status code
    • Preview: Formatted response data
    • Response: Raw response data
    • Timing: Request timing breakdown

Common issues:

401 Unauthorized:

// Check Authorization header
// Network Tab > Request Headers
Authorization: Bearer eyJhbGciOiJIUzI1...

// Check token in console
console.log(localStorage.getItem('tmi_token'));

// Decode JWT to check expiration
const token = localStorage.getItem('tmi_token');
const payload = JSON.parse(atob(token.split('.')[1]));
console.log('Token expires:', new Date(payload.exp * 1000));

CORS errors:

Access to fetch at 'https://api.example.com' from origin 'https://app.example.com'
has been blocked by CORS policy: No 'Access-Control-Allow-Origin' header is present.

Check server CORS configuration:

# Verify CORS headers
curl -H "Origin: https://app.example.com" \
     -H "Access-Control-Request-Method: GET" \
     -H "Access-Control-Request-Headers: Authorization" \
     -X OPTIONS \
     -v \
     https://api.example.com/api/v1/threat-models

Network errors:

// Check for network connectivity
fetch('https://api.example.com/health')
  .then(r => console.log('Server reachable:', r.status))
  .catch(e => console.error('Network error:', e));

Debugging WebSocket Connections

Network tab WebSocket inspection:

  1. Open Network tab
  2. Filter by "WS" or "WebSocket"
  3. Click WebSocket connection
  4. View Messages tab:
    • Outgoing messages (sent)
    • Incoming messages (received)
    • Message timestamps

Console WebSocket debugging:

// Monitor WebSocket events
const socket = new WebSocket('wss://api.example.com/ws');

socket.onopen = (e) => console.log('WebSocket connected:', e);
socket.onerror = (e) => console.error('WebSocket error:', e);
socket.onclose = (e) => console.log('WebSocket closed:', e.code, e.reason);
socket.onmessage = (e) => console.log('WebSocket message:', JSON.parse(e.data));

Common WebSocket issues:

Connection refused:

  • Check WebSocket URL (ws:// vs wss://)
  • Verify server is running
  • Check firewall/proxy settings

Connection closes immediately:

  • Check authentication (JWT token)
  • Verify CORS headers
  • Check server logs for errors

Messages not received:

  • Verify subscription is active
  • Check Redis connectivity on server
  • Monitor Network tab Messages

JavaScript Debugging

Set breakpoints:

  1. Open Sources tab
  2. Find JavaScript file
  3. Click line number to set breakpoint
  4. Trigger action to hit breakpoint
  5. Inspect variables, step through code

Console debugging:

// Log API responses
fetch('/api/v1/threat-models')
  .then(r => r.json())
  .then(data => {
    console.log('API response:', data);
    debugger; // Pause execution here
  });

// Log WebSocket messages
socket.onmessage = (e) => {
  const data = JSON.parse(e.data);
  console.table(data); // Display as table
  console.dir(data);   // Display as object
};

// Trace function calls
console.trace('Function call stack');

Database Queries

Connecting to Database

psql command line:

# Connect to database
psql -h localhost -U postgres -d tmi

# Or use environment variables
export PGHOST=localhost
export PGUSER=postgres
export PGDATABASE=tmi
psql

From Docker:

# Connect to PostgreSQL container
docker exec -it tmi-postgres psql -U postgres -d tmi

Useful Diagnostic Queries

Check active connections:

-- List all connections
SELECT pid, usename, application_name, client_addr, state, query
FROM pg_stat_activity
WHERE datname = 'tmi'
ORDER BY state, query_start DESC;

-- Count connections by state
SELECT state, COUNT(*)
FROM pg_stat_activity
WHERE datname = 'tmi'
GROUP BY state;

Check database size:

-- Database size
SELECT pg_size_pretty(pg_database_size('tmi')) AS database_size;

-- Table sizes
SELECT schemaname, tablename,
       pg_size_pretty(pg_total_relation_size(schemaname||'.'||tablename)) AS size
FROM pg_tables
WHERE schemaname = 'public'
ORDER BY pg_total_relation_size(schemaname||'.'||tablename) DESC
LIMIT 20;

-- Largest indexes
SELECT schemaname, tablename, indexname,
       pg_size_pretty(pg_relation_size(indexrelid)) AS size
FROM pg_indexes
JOIN pg_class ON pg_class.relname = indexname
WHERE schemaname = 'public'
ORDER BY pg_relation_size(indexrelid) DESC
LIMIT 10;

Check slow queries:

-- Currently running slow queries
SELECT pid, now() - query_start AS duration, state, query
FROM pg_stat_activity
WHERE state = 'active'
  AND now() - query_start > interval '5 seconds'
ORDER BY duration DESC;

-- Kill a long-running query (use carefully!)
SELECT pg_terminate_backend(pid)
FROM pg_stat_activity
WHERE pid = <process_id>;

Check table statistics:

-- Row counts
SELECT schemaname, tablename, n_live_tup AS row_count
FROM pg_stat_user_tables
WHERE schemaname = 'public'
ORDER BY n_live_tup DESC;

-- Table activity (inserts, updates, deletes)
SELECT schemaname, relname,
       seq_scan, seq_tup_read,
       idx_scan, idx_tup_fetch,
       n_tup_ins, n_tup_upd, n_tup_del
FROM pg_stat_user_tables
WHERE schemaname = 'public'
ORDER BY n_tup_ins + n_tup_upd + n_tup_del DESC;

Check indexes:

-- List all indexes
SELECT schemaname, tablename, indexname, indexdef
FROM pg_indexes
WHERE schemaname = 'public'
ORDER BY tablename, indexname;

-- Find unused indexes
SELECT schemaname, tablename, indexname, idx_scan
FROM pg_stat_user_indexes
WHERE schemaname = 'public'
  AND idx_scan = 0
  AND indexrelname NOT LIKE 'pg_toast%'
ORDER BY pg_relation_size(indexrelid) DESC;

-- Find missing indexes (high seq_scan, no idx_scan)
SELECT schemaname, tablename, seq_scan, idx_scan,
       seq_scan - idx_scan AS too_much_seq,
       CASE WHEN seq_scan - idx_scan > 0
            THEN 'Missing Index?'
            ELSE 'OK'
       END AS advice
FROM pg_stat_user_tables
WHERE schemaname = 'public'
  AND seq_scan - idx_scan > 0
ORDER BY too_much_seq DESC;

Application-specific queries:

-- Count threat models by user
SELECT owner, COUNT(*) as threat_model_count
FROM threat_models
GROUP BY owner
ORDER BY threat_model_count DESC
LIMIT 10;

-- Recent threat model activity
SELECT id, name, owner, created_at, modified_at
FROM threat_models
ORDER BY modified_at DESC
LIMIT 20;

-- Users with most authorization grants
SELECT subject, COUNT(*) as grant_count
FROM authorization
GROUP BY subject
ORDER BY grant_count DESC
LIMIT 10;

-- Webhook subscription status
SELECT status, COUNT(*) as count
FROM webhook_subscriptions
GROUP BY status;

-- Failed webhook deliveries
SELECT ws.url, wd.status, COUNT(*) as failure_count
FROM webhook_deliveries wd
JOIN webhook_subscriptions ws ON ws.id = wd.subscription_id
WHERE wd.status = 'failed'
  AND wd.created_at > NOW() - INTERVAL '24 hours'
GROUP BY ws.url, wd.status
ORDER BY failure_count DESC;

Query Performance Analysis

EXPLAIN ANALYZE:

-- Analyze query performance
EXPLAIN ANALYZE
SELECT tm.*, u.email
FROM threat_models tm
JOIN users u ON u.id = tm.owner
WHERE tm.created_at > NOW() - INTERVAL '7 days'
ORDER BY tm.created_at DESC;

-- Look for:
-- - Seq Scan (consider adding index)
-- - High execution time
-- - High row counts

Enable query logging:

-- Log slow queries (PostgreSQL config)
ALTER DATABASE tmi SET log_min_duration_statement = 1000; -- Log queries >1s

-- Log all queries (development only)
ALTER DATABASE tmi SET log_statement = 'all';

Redis Debugging

Connecting to Redis

# Connect via redis-cli
redis-cli

# Connect to specific host/port
redis-cli -h localhost -p 6379

# Connect with password
redis-cli -a yourpassword

# From Docker
docker exec -it tmi-redis redis-cli

Useful Redis Commands

Check Redis status:

# Server info
redis-cli INFO

# Memory usage
redis-cli INFO memory

# Connected clients
redis-cli CLIENT LIST

# Server statistics
redis-cli INFO stats

Inspect keys:

# Count keys
redis-cli DBSIZE

# List keys (use carefully in production!)
redis-cli KEYS "*"

# Scan keys safely (paginated)
redis-cli SCAN 0 MATCH "session:*" COUNT 100

# Get key value
redis-cli GET "session:abc123"

# Get key type and TTL
redis-cli TYPE "session:abc123"
redis-cli TTL "session:abc123"

WebSocket debugging:

# List WebSocket sessions
redis-cli KEYS "websocket:*"

# Check WebSocket connection
redis-cli GET "websocket:connection:xyz789"

# Monitor real-time commands
redis-cli MONITOR

Webhook debugging:

# Check event stream
redis-cli XINFO STREAM tmi:events

# View recent events
redis-cli XRANGE tmi:events - + COUNT 10

# Check webhook consumer group
redis-cli XINFO GROUPS tmi:events

# Check pending webhook deliveries
redis-cli XPENDING tmi:events webhook-consumers

Cache debugging:

# Check cache hit rate
redis-cli INFO stats | grep hit_rate

# Find large keys
redis-cli --bigkeys

# Sample keys
redis-cli --sample

Debugging Workflows

Debugging Authentication Issues

  1. Check logs:

    grep '"component":"auth"' logs/tmi.log | tail -20
  2. Verify OAuth configuration:

    curl http://localhost:8080/auth/github/login
  3. Check JWT token:

    // In browser console
    const token = localStorage.getItem('tmi_token');
    console.log(JSON.parse(atob(token.split('.')[1])));
  4. Test API with token:

    curl -H "Authorization: Bearer $TOKEN" \
         http://localhost:8080/api/v1/threat-models

Debugging WebSocket Issues

  1. Check server logs:

    grep '"component":"websocket"' logs/tmi.log
  2. Verify Redis connectivity:

    redis-cli PING
    redis-cli KEYS "websocket:*"
  3. Monitor WebSocket in browser:

    • Open Network tab, filter by WS
    • Check connection status and messages
  4. Test WebSocket connection:

    websocat wss://api.example.com/ws

Debugging Performance Issues

  1. Check server logs for slow requests:

    grep '"duration":[5-9][0-9][0-9]' logs/tmi.log
  2. Profile application:

    # CPU profile
    curl http://localhost:8080/debug/pprof/profile?seconds=30 > cpu.prof
    go tool pprof cpu.prof
    
    # Memory profile
    curl http://localhost:8080/debug/pprof/heap > mem.prof
    go tool pprof mem.prof
  3. Check database performance:

    -- Find slow queries
    SELECT query, calls, total_time, mean_time
    FROM pg_stat_statements
    ORDER BY mean_time DESC
    LIMIT 10;
  4. Check Redis performance:

    # Monitor commands
    redis-cli MONITOR
    
    # Check slow log
    redis-cli SLOWLOG GET 10

Related Documentation

Clone this wiki locally