organizational_intelligence_plugin/

observability.rs

//! Observability: Logging, Tracing, and Metrics
//!
//! PROD-003: Production-ready observability using tracing
//! Provides structured logging, span tracing, and performance metrics

use tracing::{debug, error, info, instrument, trace, warn};
use tracing_subscriber::{fmt, prelude::*, EnvFilter};

/// Initialize the tracing subscriber
///
/// # Arguments
/// * `verbose` - Enable debug-level logging
/// * `_json` - Reserved for JSON output (requires tracing-subscriber json feature)
pub fn init_tracing(verbose: bool, _json: bool) {
    let filter = if verbose {
        EnvFilter::new("debug")
    } else {
        EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"))
    };

    // Note: JSON output requires tracing-subscriber with "json" feature
    // For now, always use compact format
    tracing_subscriber::registry()
        .with(filter)
        .with(fmt::layer().compact())
        .init();
}

/// Initialize tracing with custom filter
pub fn init_with_filter(filter: &str) {
    let filter = EnvFilter::new(filter);
    tracing_subscriber::registry()
        .with(filter)
        .with(fmt::layer().compact())
        .init();
}

/// Span for tracking analysis operations
#[derive(Debug)]
pub struct AnalysisSpan {
    pub repo: String,
    pub operation: String,
}

impl AnalysisSpan {
    pub fn new(repo: impl Into<String>, operation: impl Into<String>) -> Self {
        Self {
            repo: repo.into(),
            operation: operation.into(),
        }
    }
}

/// Log levels for different operations
pub struct LogOps;

impl LogOps {
    /// Log start of analysis
    #[instrument(skip_all, fields(repo = %repo, commits = commits))]
    pub fn analysis_start(repo: &str, commits: usize) {
        info!("Starting repository analysis");
    }

    /// Log analysis completion
    #[instrument(skip_all, fields(repo = %repo, patterns = patterns, duration_ms = duration_ms))]
    pub fn analysis_complete(repo: &str, patterns: usize, duration_ms: u64) {
        info!("Analysis complete");
    }

    /// Log feature extraction
    #[instrument(skip_all, fields(count = count))]
    pub fn features_extracted(count: usize) {
        debug!("Features extracted");
    }

    /// Log correlation computation
    #[instrument(skip_all, fields(size = size, backend = %backend))]
    pub fn correlation_start(size: usize, backend: &str) {
        debug!("Computing correlation");
    }

    /// Log correlation result
    #[instrument(skip_all, fields(result = %format!("{:.4}", result), duration_us = duration_us))]
    pub fn correlation_complete(result: f32, duration_us: u64) {
        trace!("Correlation computed");
    }

    /// Log ML training
    #[instrument(skip_all, fields(model = %model, samples = samples))]
    pub fn training_start(model: &str, samples: usize) {
        info!("Training model");
    }

    /// Log ML training complete
    #[instrument(skip_all, fields(model = %model, accuracy = %format!("{:.2}%", accuracy * 100.0)))]
    pub fn training_complete(model: &str, accuracy: f32) {
        info!("Model training complete");
    }

    /// Log prediction
    #[instrument(skip_all, fields(model = %model))]
    pub fn prediction(model: &str, category: u8) {
        debug!(category = category, "Prediction made");
    }

    /// Log clustering
    #[instrument(skip_all, fields(k = k, samples = samples))]
    pub fn clustering_start(k: usize, samples: usize) {
        debug!("Starting clustering");
    }

    /// Log clustering complete
    #[instrument(skip_all, fields(k = k, inertia = %format!("{:.2}", inertia)))]
    pub fn clustering_complete(k: usize, inertia: f32) {
        debug!("Clustering complete");
    }

    /// Log storage operation
    #[instrument(skip_all, fields(operation = %operation, count = count))]
    pub fn storage_op(operation: &str, count: usize) {
        trace!("Storage operation");
    }

    /// Log GPU operation
    #[instrument(skip_all, fields(operation = %operation, backend = %backend))]
    pub fn gpu_op(operation: &str, backend: &str) {
        debug!("GPU operation");
    }

    /// Log error with context
    pub fn error_with_context(error: &impl std::fmt::Display, context: &str) {
        error!(context = context, error = %error, "Operation failed");
    }

    /// Log warning
    pub fn warning(message: &str, context: &str) {
        warn!(context = context, "{}", message);
    }

    /// Log performance metric
    #[instrument(skip_all, fields(operation = %operation, duration_ms = duration_ms, throughput = throughput))]
    pub fn performance(operation: &str, duration_ms: u64, throughput: Option<f64>) {
        if let Some(tp) = throughput {
            info!(throughput_per_sec = %format!("{:.2}", tp), "Performance metric");
        } else {
            info!("Performance metric");
        }
    }
}

/// Timer for measuring operation duration
pub struct Timer {
    start: std::time::Instant,
    operation: String,
}

impl Timer {
    pub fn new(operation: impl Into<String>) -> Self {
        Self {
            start: std::time::Instant::now(),
            operation: operation.into(),
        }
    }

    pub fn elapsed_ms(&self) -> u64 {
        self.start.elapsed().as_millis() as u64
    }

    pub fn elapsed_us(&self) -> u64 {
        self.start.elapsed().as_micros() as u64
    }

    pub fn log_completion(&self) {
        let duration = self.elapsed_ms();
        debug!(
            operation = %self.operation,
            duration_ms = duration,
            "Operation completed"
        );
    }
}

impl Drop for Timer {
    fn drop(&mut self) {
        // Optionally log on drop
    }
}

/// Metrics collector for aggregating statistics
#[derive(Debug, Default)]
pub struct Metrics {
    pub analyses_count: u64,
    pub features_extracted: u64,
    pub correlations_computed: u64,
    pub predictions_made: u64,
    pub errors_count: u64,
    pub total_duration_ms: u64,
}

impl Metrics {
    pub fn new() -> Self {
        Self::default()
    }

    pub fn record_analysis(&mut self, duration_ms: u64) {
        self.analyses_count += 1;
        self.total_duration_ms += duration_ms;
    }

    pub fn record_features(&mut self, count: u64) {
        self.features_extracted += count;
    }

    pub fn record_correlation(&mut self) {
        self.correlations_computed += 1;
    }

    pub fn record_prediction(&mut self) {
        self.predictions_made += 1;
    }

    pub fn record_error(&mut self) {
        self.errors_count += 1;
    }

    pub fn summary(&self) -> String {
        format!(
            "Metrics: analyses={}, features={}, correlations={}, predictions={}, errors={}, total_time={}ms",
            self.analyses_count,
            self.features_extracted,
            self.correlations_computed,
            self.predictions_made,
            self.errors_count,
            self.total_duration_ms
        )
    }

    pub fn log_summary(&self) {
        info!(
            analyses = self.analyses_count,
            features = self.features_extracted,
            correlations = self.correlations_computed,
            predictions = self.predictions_made,
            errors = self.errors_count,
            total_duration_ms = self.total_duration_ms,
            "Session metrics"
        );
    }
}

#[cfg(test)]
mod tests {
    use super::*;

    #[test]
    fn test_timer_creation() {
        let timer = Timer::new("test_operation");
        assert_eq!(timer.operation, "test_operation");
    }

    #[test]
    fn test_timer_elapsed() {
        let timer = Timer::new("test");
        std::thread::sleep(std::time::Duration::from_millis(10));
        assert!(timer.elapsed_ms() >= 10);
    }

    #[test]
    fn test_metrics_default() {
        let metrics = Metrics::new();
        assert_eq!(metrics.analyses_count, 0);
        assert_eq!(metrics.errors_count, 0);
    }

    #[test]
    fn test_metrics_recording() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(100);
        metrics.record_features(50);
        metrics.record_correlation();
        metrics.record_prediction();
        metrics.record_error();

        assert_eq!(metrics.analyses_count, 1);
        assert_eq!(metrics.features_extracted, 50);
        assert_eq!(metrics.correlations_computed, 1);
        assert_eq!(metrics.predictions_made, 1);
        assert_eq!(metrics.errors_count, 1);
        assert_eq!(metrics.total_duration_ms, 100);
    }

    #[test]
    fn test_metrics_summary() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(50);
        metrics.record_features(100);

        let summary = metrics.summary();
        assert!(summary.contains("analyses=1"));
        assert!(summary.contains("features=100"));
    }

    #[test]
    fn test_analysis_span() {
        let span = AnalysisSpan::new("owner/repo", "analyze");
        assert_eq!(span.repo, "owner/repo");
        assert_eq!(span.operation, "analyze");
    }

    #[test]
    fn test_timer_elapsed_us() {
        let timer = Timer::new("test");
        std::thread::sleep(std::time::Duration::from_micros(100));
        assert!(timer.elapsed_us() >= 100);
    }

    #[test]
    fn test_timer_log_completion() {
        let timer = Timer::new("test_op");
        timer.log_completion(); // Should not panic
    }

    #[test]
    fn test_timer_drop() {
        let _timer = Timer::new("test");
        // Drop should not panic
    }

    #[test]
    fn test_metrics_log_summary() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(100);
        metrics.log_summary(); // Should not panic
    }

    #[test]
    fn test_logops_analysis_lifecycle() {
        LogOps::analysis_start("test/repo", 100);
        LogOps::analysis_complete("test/repo", 42, 1000);
    }

    #[test]
    fn test_logops_features() {
        LogOps::features_extracted(50);
    }

    #[test]
    fn test_logops_correlation() {
        LogOps::correlation_start(100, "simd");
        LogOps::correlation_complete(0.95, 5000);
    }

    #[test]
    fn test_logops_ml_training() {
        LogOps::training_start("k-means", 100);
        LogOps::training_complete("k-means", 0.85);
    }

    #[test]
    fn test_logops_prediction() {
        LogOps::prediction("DefectPredictor", 3);
    }

    #[test]
    fn test_logops_clustering() {
        LogOps::clustering_start(5, 100);
        LogOps::clustering_complete(5, 123.45);
    }

    #[test]
    fn test_logops_storage() {
        LogOps::storage_op("save", 100);
    }

    #[test]
    fn test_logops_gpu() {
        LogOps::gpu_op("correlate", "gpu");
    }

    #[test]
    fn test_logops_error_with_context() {
        let error = std::io::Error::other("test error");
        LogOps::error_with_context(&error, "during analysis");
    }

    #[test]
    fn test_logops_warning() {
        LogOps::warning("low memory", "performance");
    }

    #[test]
    fn test_logops_performance_with_throughput() {
        LogOps::performance("analysis", 1000, Some(100.5));
    }

    #[test]
    fn test_logops_performance_without_throughput() {
        LogOps::performance("analysis", 1000, None);
    }

    #[test]
    fn test_multiple_metrics_recordings() {
        let mut metrics = Metrics::new();
        for i in 0..10 {
            metrics.record_analysis(i * 10);
            metrics.record_features(i * 5);
        }
        assert_eq!(metrics.analyses_count, 10);
        assert_eq!(metrics.features_extracted, 225); // 0+5+10+...+45
        assert_eq!(metrics.total_duration_ms, 450); // 0+10+20+...+90
    }

    #[test]
    fn test_metrics_default_trait() {
        let metrics = Metrics::default();
        assert_eq!(metrics.analyses_count, 0);
        assert_eq!(metrics.features_extracted, 0);
        assert_eq!(metrics.correlations_computed, 0);
        assert_eq!(metrics.predictions_made, 0);
        assert_eq!(metrics.errors_count, 0);
        assert_eq!(metrics.total_duration_ms, 0);
    }

    #[test]
    fn test_timer_with_string_operation() {
        let timer = Timer::new(String::from("string_op"));
        assert_eq!(timer.operation, "string_op");
    }

    #[test]
    fn test_timer_elapsed_immediately() {
        let timer = Timer::new("instant");
        let elapsed = timer.elapsed_ms();
        // Just verify it returns without panic (elapsed is always >= 0 for u64)
        assert!(elapsed < 1000); // Should be < 1 second
    }

    #[test]
    fn test_analysis_span_with_string() {
        let span = AnalysisSpan::new(String::from("owner/repo"), String::from("op"));
        assert_eq!(span.repo, "owner/repo");
        assert_eq!(span.operation, "op");
    }

    #[test]
    fn test_metrics_multiple_errors() {
        let mut metrics = Metrics::new();
        for _ in 0..5 {
            metrics.record_error();
        }
        assert_eq!(metrics.errors_count, 5);
    }

    #[test]
    fn test_metrics_multiple_predictions() {
        let mut metrics = Metrics::new();
        for _ in 0..10 {
            metrics.record_prediction();
        }
        assert_eq!(metrics.predictions_made, 10);
    }

    #[test]
    fn test_metrics_multiple_correlations() {
        let mut metrics = Metrics::new();
        for _ in 0..3 {
            metrics.record_correlation();
        }
        assert_eq!(metrics.correlations_computed, 3);
    }

    #[test]
    fn test_metrics_zero_duration() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(0);
        assert_eq!(metrics.analyses_count, 1);
        assert_eq!(metrics.total_duration_ms, 0);
    }

    #[test]
    fn test_metrics_large_duration() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(1_000_000);
        assert_eq!(metrics.total_duration_ms, 1_000_000);
    }

    #[test]
    fn test_metrics_summary_contains_all_fields() {
        let mut metrics = Metrics::new();
        metrics.record_analysis(100);
        metrics.record_features(50);
        metrics.record_correlation();
        metrics.record_prediction();
        metrics.record_error();

        let summary = metrics.summary();
        assert!(summary.contains("analyses="));
        assert!(summary.contains("features="));
        assert!(summary.contains("correlations="));
        assert!(summary.contains("predictions="));
        assert!(summary.contains("errors="));
        assert!(summary.contains("total_time="));
    }

    #[test]
    fn test_timer_microsecond_precision() {
        let timer = Timer::new("precision_test");
        std::thread::sleep(std::time::Duration::from_micros(500));
        let us = timer.elapsed_us();
        let ms = timer.elapsed_ms();

        // Microseconds should be at least 500
        assert!(us >= 500);
        // Microseconds should be at least milliseconds * 1000 (rough conversion)
        assert!(us >= ms * 1000);
    }

    #[test]
    fn test_analysis_span_debug() {
        let span = AnalysisSpan::new("test/repo", "operation");
        let debug_str = format!("{:?}", span);
        assert!(debug_str.contains("AnalysisSpan"));
    }

    #[test]
    fn test_metrics_debug() {
        let metrics = Metrics::new();
        let debug_str = format!("{:?}", metrics);
        assert!(debug_str.contains("Metrics"));
    }

    #[test]
    fn test_logops_all_operations_no_panic() {
        // Ensure all LogOps methods work without panicking
        LogOps::analysis_start("repo", 100);
        LogOps::analysis_complete("repo", 10, 1000);
        LogOps::features_extracted(50);
        LogOps::correlation_start(100, "cpu");
        LogOps::correlation_complete(0.5, 1000);
        LogOps::training_start("model", 100);
        LogOps::training_complete("model", 0.9);
        LogOps::prediction("model", 1);
        LogOps::clustering_start(3, 100);
        LogOps::clustering_complete(3, 50.0);
        LogOps::storage_op("load", 50);
        LogOps::gpu_op("compute", "gpu");

        let err = std::io::Error::other("test");
        LogOps::error_with_context(&err, "test context");
        LogOps::warning("test warning", "test");
        LogOps::performance("op", 100, Some(10.0));
        LogOps::performance("op", 100, None);
    }

    #[test]
    fn test_metrics_accumulation() {
        let mut metrics = Metrics::new();

        // Record multiple analyses with different durations
        metrics.record_analysis(100);
        metrics.record_analysis(200);
        metrics.record_analysis(300);

        assert_eq!(metrics.analyses_count, 3);
        assert_eq!(metrics.total_duration_ms, 600);

        // Record multiple features
        metrics.record_features(10);
        metrics.record_features(20);

        assert_eq!(metrics.features_extracted, 30);
    }
}