plans/performance-observability.md

# Performance & Observability Enhancement Plan

## Current State Analysis

**Observability**:
- Basic logging with logrus
- No structured logging standards
- No distributed tracing
- No metrics collection
- No health check endpoints

**Performance**:
- No caching layer
- No connection pooling for upstream APIs
- No circuit breakers
- No request coalescing
- No rate limiting per API key

## Phase 1: Structured Logging (Week 1)

### 1.1 Migrate to slog (Go 1.21+)
**File**: `internal/infrastructure/logging/logger.go`

```go
package logging

import (
	"context"
	"log/slog"
	"os"

	"github.com/google/uuid"
)

// Logger wraps slog with application-specific methods
type Logger struct {
	*slog.Logger
}

// Config for logger
type Config struct {
	Level  string `json:"level"`
	Format string `json:"format"` // json or text
	Output string `json:"output"` // stdout, stderr, or file path
}

func New(cfg Config) (*Logger, error) {
	level := parseLevel(cfg.Level)

	var handler slog.Handler
	opts := &slog.HandlerOptions{
		Level:     level,
		AddSource: true,
	}

	switch cfg.Format {
	case "json":
		handler = slog.NewJSONHandler(os.Stdout, opts)
	case "text":
		handler = slog.NewTextHandler(os.Stdout, opts)
	default:
		handler = slog.NewJSONHandler(os.Stdout, opts)
	}

	return &Logger{Logger: slog.New(handler)}, nil
}

// WithContext adds request context fields
func (l *Logger) WithContext(ctx context.Context) *Logger {
	return &Logger{
		Logger: l.Logger.With(
			"request_id", ctx.Value(RequestIDKey{}),
			"trace_id", ctx.Value(TraceIDKey{}),
		),
	}
}

// WithError adds error field
func (l *Logger) WithError(err error) *Logger {
	return &Logger{
		Logger: l.Logger.With("error", err),
	}
}

// WithField adds a single field
func (l *Logger) WithField(key string, value interface{}) *Logger {
	return &Logger{
		Logger: l.Logger.With(key, value),
	}
}

// WithFields adds multiple fields
func (l *Logger) WithFields(fields map[string]interface{}) *Logger {
	attrs := make([]slog.Attr, 0, len(fields))
	for k, v := range fields {
		attrs = append(attrs, slog.Any(k, v))
	}
	return &Logger{Logger: slog.New(l.Logger.Handler().WithAttrs(attrs))}
}

// Request logging helper
func (l *Logger) LogRequest(
	ctx context.Context,
	method string,
	path string,
	status int,
	duration time.Duration,
	extra map[string]interface{},
) {
	fields := map[string]interface{}{
		"http.method":     method,
		"http.path":       path,
		"http.status":     status,
		"duration_ms":     duration.Milliseconds(),
		"duration_bucket": durationBucket(duration),
	}
	for k, v := range extra {
		fields[k] = v
	}

	logger := l.WithContext(ctx).WithFields(fields)

	switch {
	case status >= 500:
		logger.Error("HTTP request completed with server error")
	case status >= 400:
		logger.Warn("HTTP request completed with client error")
	case status >= 300:
		logger.Info("HTTP request redirected")
	default:
		logger.Info("HTTP request completed")
	}
}

func durationBucket(d time.Duration) string {
	switch {
	case d < 10*time.Millisecond:
		return "<10ms"
	case d < 50*time.Millisecond:
		return "10-50ms"
	case d < 100*time.Millisecond:
		return "50-100ms"
	case d < 500*time.Millisecond:
		return "100-500ms"
	case d < 1*time.Second:
		return "500ms-1s"
	default:
		return ">1s"
	}
}
```

### 1.2 Gin Middleware
**File**: `internal/api/middleware/logging.go`

```go
package middleware

import (
	"time"

	"github.com/gin-gonic/gin"

	"github.com/echyai/cliproxyapi/internal/infrastructure/logging"
)

func RequestLogger(logger *logging.Logger) gin.HandlerFunc {
	return func(c *gin.Context) {
		start := time.Now()

		// Process request
		c.Next()

		// Log after request completes
		duration := time.Since(start)

		extra := map[string]interface{}{
			"client_ip":  c.ClientIP(),
			"user_agent": c.Request.UserAgent(),
			"errors":     c.Errors.String(),
		}

		logger.LogRequest(
			c.Request.Context(),
			c.Request.Method,
			c.Request.URL.Path,
			c.Writer.Status(),
			duration,
			extra,
		)
	}
}
```

## Phase 2: Distributed Tracing (Week 2)

### 2.1 OpenTelemetry Setup
**File**: `internal/infrastructure/tracing/tracing.go`

```go
package tracing

import (
	"context"

	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/exporters/jaeger"
	"go.opentelemetry.io/otel/sdk/resource"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	semconv "go.opentelemetry.io/otel/semconv/v1.24.0"
	"go.opentelemetry.io/otel/trace"
)

var Tracer trace.Tracer

func Init(serviceName, jaegerEndpoint string) (*sdktrace.TracerProvider, error) {
	exp, err := jaeger.New(jaeger.WithCollectorEndpoint(
		jaeger.WithEndpoint(jaegerEndpoint),
	))
	if err != nil {
		return nil, err
	}

	tp := sdktrace.NewTracerProvider(
		sdktrace.WithBatcher(exp),
		sdktrace.WithResource(resource.NewWithAttributes(
			semconv.SchemaURL,
			semconv.ServiceName(serviceName),
			semconv.ServiceVersion("1.0.0"),
		)),
	)

	otel.SetTracerProvider(tp)
	Tracer = tp.Tracer(serviceName)

	return tp, nil
}

// SpanFromContext retrieves current span
func SpanFromContext(ctx context.Context) trace.Span {
	return trace.SpanFromContext(ctx)
}

// StartSpan starts a new span
func StartSpan(ctx context.Context, name string, opts ...trace.SpanStartOption) (context.Context, trace.Span) {
	return Tracer.Start(ctx, name, opts...)
}
```

### 2.2 Gin Tracing Middleware
**File**: `internal/api/middleware/tracing.go`

```go
package middleware

import (
	"github.com/gin-gonic/gin"
	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/propagation"
	semconv "go.opentelemetry.io/otel/semconv/v1.24.0"
	"go.opentelemetry.io/otel/trace"

	"github.com/echyai/cliproxyapi/internal/infrastructure/tracing"
)

func Tracing() gin.HandlerFunc {
	return func(c *gin.Context) {
		// Extract trace context from headers
		ctx := propagation.TraceContext{}.Extract(c.Request.Context(),
			propagation.HeaderCarrier(c.Request.Header))

		// Start span
		ctx, span := tracing.StartSpan(ctx,
			c.Request.Method+" "+c.FullPath(),
			trace.WithAttributes(
				semconv.HTTPMethod(c.Request.Method),
				semconv.HTTPURL(c.Request.URL.String()),
				semconv.HTTPUserAgent(c.Request.UserAgent()),
				semconv.HTTPClientIP(c.ClientIP()),
			),
		)
		defer span.End()

		// Add span to context
		c.Request = c.Request.WithContext(ctx)

		// Continue
		c.Next()

		// Record result
		span.SetAttributes(
			semconv.HTTPStatusCode(c.Writer.Status()),
		)

		if c.Writer.Status() >= 400 {
			span.RecordError(c.Errors.Last())
		}
	}
}
```

## Phase 3: Metrics Collection (Week 2-3)

### 3.1 Prometheus Metrics
**File**: `internal/infrastructure/metrics/metrics.go`

```go
package metrics

import (
	"github.com/prometheus/client_golang/prometheus"
	"github.com/prometheus/client_golang/prometheus/promauto"
)

var (
	// HTTP metrics
	HTTPRequestsTotal = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_http_requests_total",
			Help: "Total HTTP requests",
		},
		[]string{"method", "path", "status"},
	)

	HTTPRequestDuration = promauto.NewHistogramVec(
		prometheus.HistogramOpts{
			Name:    "cliproxy_http_request_duration_seconds",
			Help:    "HTTP request duration in seconds",
			Buckets: []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10},
		},
		[]string{"method", "path"},
	)

	// Provider metrics
	ProviderRequestsTotal = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_provider_requests_total",
			Help: "Total requests to upstream providers",
		},
		[]string{"provider", "model", "status"},
	)

	ProviderRequestDuration = promauto.NewHistogramVec(
		prometheus.HistogramOpts{
			Name:    "cliproxy_provider_request_duration_seconds",
			Help:    "Upstream provider request duration",
			Buckets: []float64{.1, .25, .5, 1, 2.5, 5, 10, 30, 60},
		},
		[]string{"provider", "model"},
	)

	ProviderTokensTotal = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_provider_tokens_total",
			Help: "Total tokens processed",
		},
		[]string{"provider", "model", "type"}, // type: input, output
	)

	// Rate limiting metrics
	RateLimitHits = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_rate_limit_hits_total",
			Help: "Total rate limit hits",
		},
		[]string{"key_type", "key_id"},
	)

	// Cache metrics
	CacheHits = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_cache_hits_total",
			Help: "Total cache hits",
		},
		[]string{"cache_name"},
	)

	CacheMisses = promauto.NewCounterVec(
		prometheus.CounterOpts{
			Name: "cliproxy_cache_misses_total",
			Help: "Total cache misses",
		},
		[]string{"cache_name"},
	)

	// Active connections
	ActiveConnections = promauto.NewGauge(
		prometheus.GaugeOpts{
			Name: "cliproxy_active_connections",
			Help: "Number of active connections",
		},
	)

	// Auth metrics
	ActiveAuths = promauto.NewGaugeVec(
		prometheus.GaugeOpts{
			Name: "cliproxy_active_auths",
			Help: "Number of active authentications",
		},
		[]string{"provider"},
	)
)
```

### 3.2 Gin Metrics Middleware
**File**: `internal/api/middleware/metrics.go`

```go
package middleware

import (
	"strconv"
	"time"

	"github.com/gin-gonic/gin"
	"github.com/prometheus/client_golang/prometheus"

	"github.com/echyai/cliproxyapi/internal/infrastructure/metrics"
)

func PrometheusMetrics() gin.HandlerFunc {
	return func(c *gin.Context) {
		start := time.Now()

		c.Next()

		duration := time.Since(start).Seconds()
		status := strconv.Itoa(c.Writer.Status())
		path := c.FullPath()
		if path == "" {
			path = "unknown"
		}

		metrics.HTTPRequestsTotal.WithLabelValues(
			c.Request.Method,
			path,
			status,
		).Inc()

		metrics.HTTPRequestDuration.WithLabelValues(
			c.Request.Method,
			path,
		).Observe(duration)
	}
}
```

## Phase 4: Caching Layer (Week 3)

### 4.1 Cache Interface
**File**: `internal/infrastructure/cache/cache.go`

```go
package cache

import (
	"context"
	"time"
)

// Cache interface for different backends
type Cache interface {
	Get(ctx context.Context, key string) ([]byte, error)
	Set(ctx context.Context, key string, value []byte, ttl time.Duration) error
	Delete(ctx context.Context, key string) error
	GetSetMembers(ctx context.Context, key string) ([]string, error)
	AddToSet(ctx context.Context, key string, members ...string) error
	Close() error
}

// Config for cache
type Config struct {
	Type   string // redis, inmemory
	Redis  *RedisConfig
	Memory *MemoryConfig
}

type RedisConfig struct {
	Addr     string
	Password string
	DB       int
}

type MemoryConfig struct {
	MaxSize int // Maximum number of items
}
```

### 4.2 Token Cache Implementation
**File**: `internal/infrastructure/cache/token_cache.go`

```go
package cache

import (
	"context"
	"encoding/json"
	"fmt"
	"time"

	"github.com/echyai/cliproxyapi/internal/domain/entities"
)

// TokenCache provides caching for OAuth tokens
type TokenCache struct {
	cache Cache
	ttl   time.Duration
}

func NewTokenCache(cache Cache, ttl time.Duration) *TokenCache {
	return &TokenCache{
		cache: cache,
		ttl:   ttl,
	}
}

func (tc *TokenCache) Get(ctx context.Context, authID entities.AuthID) (*entities.TokenData, error) {
	key := fmt.Sprintf("token:%s", authID)

	data, err := tc.cache.Get(ctx, key)
	if err != nil {
		return nil, err
	}
	if data == nil {
		return nil, nil
	}

	var token entities.TokenData
	if err := json.Unmarshal(data, &token); err != nil {
		return nil, err
	}

	return &token, nil
}

func (tc *TokenCache) Set(ctx context.Context, authID entities.AuthID, token *entities.TokenData) error {
	key := fmt.Sprintf("token:%s", authID)

	data, err := json.Marshal(token)
	if err != nil {
		return err
	}

	return tc.cache.Set(ctx, key, data, tc.ttl)
}

func (tc *TokenCache) Invalidate(ctx context.Context, authID entities.AuthID) error {
	key := fmt.Sprintf("token:%s", authID)
	return tc.cache.Delete(ctx, key)
}
```

## Phase 5: Circuit Breaker (Week 4)

### 5.1 Circuit Breaker Implementation
**File**: `internal/infrastructure/resilience/circuit_breaker.go`

```go
package resilience

import (
	"context"
	"errors"
	"sync"
	"time"
)

// State represents circuit breaker state
type State int

const (
	StateClosed State = iota
	StateOpen
	StateHalfOpen
)

func (s State) String() string {
	switch s {
	case StateClosed:
		return "closed"
	case StateOpen:
		return "open"
	case StateHalfOpen:
		return "half-open"
	default:
		return "unknown"
	}
}

// Config for circuit breaker
type Config struct {
	FailureThreshold int           // Number of failures before opening
	SuccessThreshold int           // Number of successes to close from half-open
	Timeout          time.Duration // Time before attempting half-open
	HalfOpenMaxCalls int           // Max calls allowed in half-open state
}

// CircuitBreaker implements the circuit breaker pattern
type CircuitBreaker struct {
	name           string
	config         Config
	state          State
	failures       int
	successes      int
	lastFailure    time.Time
	halfOpenCalls  int
	mu             sync.RWMutex
	onStateChange  func(name string, from, to State)
}

func New(name string, config Config, onStateChange func(string, State, State)) *CircuitBreaker {
	return &CircuitBreaker{
		name:          name,
		config:        config,
		state:         StateClosed,
		onStateChange: onStateChange,
	}
}

func (cb *CircuitBreaker) Execute(ctx context.Context, fn func() error) error {
	cb.mu.Lock()
	state := cb.state

	switch state {
	case StateOpen:
		if time.Since(cb.lastFailure) > cb.config.Timeout {
			cb.transitionTo(StateHalfOpen)
			state = StateHalfOpen
		} else {
			cb.mu.Unlock()
			return errors.New("circuit breaker is open")
		}
	case StateHalfOpen:
		if cb.halfOpenCalls >= cb.config.HalfOpenMaxCalls {
			cb.mu.Unlock()
			return errors.New("circuit breaker half-open call limit reached")
		}
		cb.halfOpenCalls++
	}
	cb.mu.Unlock()

	// Execute function
	err := fn()

	cb.recordResult(err)
	return err
}

func (cb *CircuitBreaker) recordResult(err error) {
	cb.mu.Lock()
	defer cb.mu.Unlock()

	if err == nil {
		cb.onSuccess()
	} else {
		cb.onFailure()
	}
}

func (cb *CircuitBreaker) onSuccess() {
	switch cb.state {
	case StateHalfOpen:
		cb.successes++
		if cb.successes >= cb.config.SuccessThreshold {
			cb.transitionTo(StateClosed)
		}
	default:
		cb.failures = 0
	}
}

func (cb *CircuitBreaker) onFailure() {
	cb.failures++
	cb.lastFailure = time.Now()

	switch cb.state {
	case StateHalfOpen:
		cb.transitionTo(StateOpen)
	default:
		if cb.failures >= cb.config.FailureThreshold {
			cb.transitionTo(StateOpen)
		}
	}
}

func (cb *CircuitBreaker) transitionTo(newState State) {
	if cb.state != newState {
		oldState := cb.state
		cb.state = newState
		cb.failures = 0
		cb.successes = 0
		cb.halfOpenCalls = 0

		if cb.onStateChange != nil {
			cb.onStateChange(cb.name, oldState, newState)
		}
	}
}

func (cb *CircuitBreaker) State() State {
	cb.mu.RLock()
	defer cb.mu.RUnlock()
	return cb.state
}
```

### 5.2 Provider Client with Circuit Breaker
**File**: `internal/infrastructure/providers/gemini_client.go`

```go
package providers

import (
	"context"
	"fmt"
	"time"

	"github.com/echyai/cliproxyapi/internal/infrastructure/metrics"
	"github.com/echyai/cliproxyapi/internal/infrastructure/resilience"
)

type GeminiClient struct {
	baseURL        string
	apiKey         string
	httpClient     *http.Client
	circuitBreaker *resilience.CircuitBreaker
	logger         *logging.Logger
}

func NewGeminiClient(baseURL, apiKey string, logger *logging.Logger) *GeminiClient {
	cb := resilience.New("gemini", resilience.Config{
		FailureThreshold: 5,
		SuccessThreshold: 2,
		Timeout:          30 * time.Second,
		HalfOpenMaxCalls: 3,
	}, func(name string, from, to resilience.State) {
		logger.WithFields(map[string]interface{}{
			"circuit_breaker": name,
			"from_state":      from.String(),
			"to_state":        to.String(),
		}).Warn("Circuit breaker state changed")
	})

	return &GeminiClient{
		baseURL: baseURL,
		apiKey:  apiKey,
		httpClient: &http.Client{
			Timeout: 60 * time.Second,
			Transport: &http.Transport{
				MaxIdleConns:        100,
				MaxIdleConnsPerHost: 10,
				IdleConnTimeout:     90 * time.Second,
			},
		},
		circuitBreaker: cb,
		logger:         logger,
	}
}

func (c *GeminiClient) GenerateContent(
	ctx context.Context,
	req *GenerateContentRequest,
) (*GenerateContentResponse, error) {
	start := time.Now()
	model := req.Model

	var resp *GenerateContentResponse
	var err error

	cbErr := c.circuitBreaker.Execute(ctx, func() error {
		resp, err = c.doGenerateContent(ctx, req)
		return err
	})

	if cbErr != nil {
		return nil, fmt.Errorf("circuit breaker: %w", cbErr)
	}

	// Record metrics
	duration := time.Since(start).Seconds()
	status := "success"
	if err != nil {
		status = "error"
	}

	metrics.ProviderRequestsTotal.WithLabelValues("gemini", model, status).Inc()
	metrics.ProviderRequestDuration.WithLabelValues("gemini", model).Observe(duration)

	if err != nil {
		return nil, err
	}

	// Record token metrics
	if resp.Usage != nil {
		metrics.ProviderTokensTotal.WithLabelValues("gemini", model, "input").
			Add(float64(resp.Usage.InputTokens))
		metrics.ProviderTokensTotal.WithLabelValues("gemini", model, "output").
			Add(float64(resp.Usage.OutputTokens))
	}

	return resp, nil
}
```

## Phase 6: Health Checks (Week 4)

**File**: `internal/api/handlers/health_handler.go`

```go
package handlers

import (
	"net/http"

	"github.com/gin-gonic/gin"

	"github.com/echyai/cliproxyapi/internal/infrastructure/health"
)

type HealthHandler struct {
	checker *health.Checker
}

func NewHealthHandler(checker *health.Checker) *HealthHandler {
	return &HealthHandler{checker: checker}
}

func (h *HealthHandler) Register(r *gin.RouterGroup) {
	r.GET("/health", h.Liveness)
	r.GET("/ready", h.Readiness)
	r.GET("/metrics", gin.WrapH(promhttp.Handler()))
}

func (h *HealthHandler) Liveness(c *gin.Context) {
	c.JSON(http.StatusOK, gin.H{
		"status": "alive",
		"time":   time.Now().UTC(),
	})
}

func (h *HealthHandler) Readiness(c *gin.Context) {
	checks := h.checker.RunAll(c.Request.Context())

	status := http.StatusOK
	for _, check := range checks {
		if !check.Healthy {
			status = http.StatusServiceUnavailable
			break
		}
	}

	c.JSON(status, gin.H{
		"status":  map[bool]string{true: "ready", false: "not_ready"}[status == http.StatusOK],
		"checks":  checks,
		"version": version.Get(),
	})
}
```

## Success Metrics

- [ ] < 50ms p99 latency for cached token lookups
- [ ] 99.9% availability measured via health checks
- [ ] < 1% request error rate
- [ ] All requests have distributed trace IDs
- [ ] Dashboard with key metrics in Grafana