ggen-core 26.7.2

//! Simple tracing system for pipeline debugging
//!
//! This module provides a lightweight tracing system for debugging template processing
//! and generation operations. It uses environment variables for configuration and
//! provides structured logging for key pipeline operations.
//!
//! ## Features
//!
//! - **Environment-based configuration**: Controlled via `GGEN_TRACE` environment variable
//! - **Multiple trace levels**: Error, Warn, Info, Debug, Trace
//! - **Performance timing**: Built-in timer for measuring operation duration
//! - **Structured logging**: Context-aware logging for templates, RDF, SPARQL, etc.
//!
//! ## Configuration
//!
//! Set the `GGEN_TRACE` environment variable to enable tracing:
//!
//! - `error` - Only error messages
//! - `warn` - Warnings and errors
//! - `info` - Informational messages (default)
//! - `debug` - Debug information
//! - `trace` - Verbose trace information
//! - `1`, `true`, `yes` - Enable debug level
//! - `0`, `false`, `no` - Disable (error only)
//!
//! ## Examples
//!
//! ### Basic Usage
//!
//! ```rust,no_run
//! use crate::simple_tracing::SimpleTracer;
//! use std::path::Path;
//!
//! // Check if tracing is enabled
//! if SimpleTracer::is_enabled() {
//!     SimpleTracer::template_start(Path::new("template.tmpl"));
//! }
//! ```
//!
//! ### Performance Timing
//!
//! ```rust,no_run
//! use crate::simple_tracing::SimpleTimer;
//!
//! let timer = SimpleTimer::start("template_processing");
//! // ... do work ...
//! timer.finish(); // Automatically logs the duration
//! ```
//!
//! ### Using the Macro
//!
//! ```rust,no_run
//! use crate::time_operation;
//!
//! let result = time_operation!("expensive_operation", {
//!     // ... operation code ...
//!     42
//! });
//! ```

/// Macro to time an operation and record it in the current trace.
#[macro_export]
macro_rules! simple_time_operation {
    ($name:expr, $block:block) => {{
        let start = std::time::Instant::now();
        let result = $block;
        let elapsed = start.elapsed();
        $crate::simple_tracing::SimpleTracer::performance($name, elapsed.as_millis() as u64);
        result
    }};
}

use std::path::Path;
use std::time::Instant;

/// Simple tracing system for pipeline debugging
pub struct SimpleTracer;

impl SimpleTracer {
    /// Check if tracing is enabled
    pub fn is_enabled() -> bool {
        std::env::var("GGEN_TRACE").is_ok()
    }

    /// Get trace level
    pub fn trace_level() -> TraceLevel {
        match std::env::var("GGEN_TRACE")
            .unwrap_or_default()
            .to_lowercase()
            .as_str()
        {
            "error" => TraceLevel::Error,
            "warn" => TraceLevel::Warn,
            "info" => TraceLevel::Info,
            "debug" => TraceLevel::Debug,
            "trace" => TraceLevel::Trace,
            "1" | "true" | "yes" => TraceLevel::Debug,
            "0" | "false" | "no" => TraceLevel::Error,
            _ => TraceLevel::Info,
        }
    }

    /// Log a trace message
    pub fn trace(level: TraceLevel, message: &str, context: Option<&str>) {
        if !Self::is_enabled() {
            return;
        }

        let current_level = Self::trace_level();
        if level as u8 > current_level as u8 {
            return;
        }

        let prefix = match level {
            TraceLevel::Error => "ERROR",
            TraceLevel::Warn => "WARN ",
            TraceLevel::Info => "INFO ",
            TraceLevel::Debug => "DEBUG",
            TraceLevel::Trace => "TRACE",
        };

        match level {
            TraceLevel::Error => {
                if let Some(ctx) = context {
                    log::error!("[GGEN {}] {}: {}", prefix, ctx, message);
                } else {
                    log::error!("[GGEN {}] {}", prefix, message);
                }
            }
            TraceLevel::Warn => {
                if let Some(ctx) = context {
                    log::warn!("[GGEN {}] {}: {}", prefix, ctx, message);
                } else {
                    log::warn!("[GGEN {}] {}", prefix, message);
                }
            }
            TraceLevel::Info => {
                if let Some(ctx) = context {
                    log::info!("[GGEN {}] {}: {}", prefix, ctx, message);
                } else {
                    log::info!("[GGEN {}] {}", prefix, message);
                }
            }
            TraceLevel::Debug | TraceLevel::Trace => {
                if let Some(ctx) = context {
                    log::debug!("[GGEN {}] {}: {}", prefix, ctx, message);
                } else {
                    log::debug!("[GGEN {}] {}", prefix, message);
                }
            }
        }
    }

    /// Log template processing start
    pub fn template_start(template_path: &Path) {
        Self::trace(
            TraceLevel::Info,
            &format!("Starting template processing: {}", template_path.display()),
            None,
        );
    }

    /// Log template processing completion
    pub fn template_complete(template_path: &Path, output_path: &Path, content_size: usize) {
        Self::trace(
            TraceLevel::Info,
            &format!(
                "Template processing complete: {} -> {} ({} bytes)",
                template_path.display(),
                output_path.display(),
                content_size
            ),
            None,
        );
    }

    /// Log frontmatter processing
    pub fn frontmatter_processed(frontmatter: &crate::template_types::Frontmatter) {
        Self::trace(
            TraceLevel::Debug,
            &format!(
                "Frontmatter processed: to={:?}, inject={}",
                frontmatter.to,
                frontmatter.flags.inject // ❌ REMOVED: vars count - no longer in frontmatter
            ),
            Some("frontmatter"),
        );
    }

    /// Log context blessing
    pub fn context_blessed(vars_count: usize) {
        Self::trace(
            TraceLevel::Debug,
            &format!(
                "Context blessed: {} variables (Name, locals added)",
                vars_count
            ),
            Some("context"),
        );
    }

    /// Log RDF loading
    pub fn rdf_loading(files: &[String], inline_blocks: usize, triples: usize) {
        Self::trace(
            TraceLevel::Info,
            &format!(
                "RDF loaded: {} files, {} inline blocks, {} triples",
                files.len(),
                inline_blocks,
                triples
            ),
            Some("rdf"),
        );
    }

    /// Log SPARQL query
    pub fn sparql_query(query: &str, result_count: Option<usize>) {
        let count_str = result_count
            .map(|c| c.to_string())
            .unwrap_or_else(|| "N/A".to_string());
        Self::trace(
            TraceLevel::Debug,
            &format!("SPARQL query: {} results", count_str),
            Some("sparql"),
        );
        Self::trace(TraceLevel::Trace, query, Some("sparql"));
    }

    /// Log file injection
    pub fn file_injection(target_path: &Path, mode: &str, success: bool) {
        let status = if success { "completed" } else { "failed" };
        Self::trace(
            TraceLevel::Info,
            &format!("File injection {}: {} mode", status, mode),
            Some(&format!("injection:{}", target_path.display())),
        );
    }

    /// Log shell hook
    pub fn shell_hook(command: &str, timing: &str, exit_code: i32) {
        let status = if exit_code == 0 {
            "completed"
        } else {
            "failed"
        };
        Self::trace(
            TraceLevel::Info,
            &format!(
                "Shell hook {}: {} (exit code: {})",
                status, timing, exit_code
            ),
            Some(&format!("hook:{}", command)),
        );
    }

    /// Log performance metric
    pub fn performance(operation: &str, duration_ms: u64) {
        Self::trace(
            TraceLevel::Debug,
            &format!("Performance: {} took {}ms", operation, duration_ms),
            Some("performance"),
        );
    }

    /// Log dry run
    pub fn dry_run(output_path: &Path, content_size: usize) {
        Self::trace(
            TraceLevel::Info,
            &format!(
                "DRY RUN: Would generate {} ({} bytes)",
                output_path.display(),
                content_size
            ),
            Some("dry_run"),
        );
    }

    /// Log backup creation
    pub fn backup_created(original_path: &Path, backup_path: &Path) {
        Self::trace(
            TraceLevel::Info,
            &format!(
                "Backup created: {} -> {}",
                original_path.display(),
                backup_path.display()
            ),
            Some("backup"),
        );
    }

    /// Log skip condition
    pub fn skip_condition(condition: &str, reason: &str) {
        Self::trace(
            TraceLevel::Info,
            &format!("Skipped: {} ({})", condition, reason),
            Some("skip"),
        );
    }

    /// Log error
    pub fn error(error: &crate::utils::error::Error, context: &str) {
        Self::trace(
            TraceLevel::Error,
            &format!("Error in {}: {}", context, error),
            Some("error"),
        );
    }

    /// Log warning
    pub fn warning(message: &str, context: Option<&str>) {
        Self::trace(TraceLevel::Warn, message, context);
    }
}

#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord)]
pub enum TraceLevel {
    Error = 0,
    Warn = 1,
    Info = 2,
    Debug = 3,
    Trace = 4,
}

/// Performance timer for measuring operation duration
pub struct SimpleTimer {
    start: Instant,
    operation: String,
}

impl SimpleTimer {
    /// Start timing an operation
    pub fn start(operation: &str) -> Self {
        Self {
            start: Instant::now(),
            operation: operation.to_string(),
        }
    }

    /// Finish timing and log the result
    pub fn finish(self) {
        let duration = self.start.elapsed();
        SimpleTracer::performance(&self.operation, duration.as_millis() as u64);
    }
}

#[cfg(test)]
mod tests {
    use super::*;
    use crate::time_operation;
    use std::fs;
    use tempfile::TempDir;

    #[test]
    fn test_trace_level_ordering() {
        assert!(TraceLevel::Error < TraceLevel::Warn);
        assert!(TraceLevel::Warn < TraceLevel::Info);
        assert!(TraceLevel::Info < TraceLevel::Debug);
        assert!(TraceLevel::Debug < TraceLevel::Trace);
    }

    #[test]
    fn test_simple_timer() {
        let timer = SimpleTimer::start("test_operation");
        std::thread::sleep(std::time::Duration::from_millis(10));
        timer.finish(); // Should not panic
    }

    #[test]
    fn test_tracing_methods() {
        let temp_dir = TempDir::new().unwrap();
        let test_path = temp_dir.path().join("test.tmpl");
        fs::write(&test_path, "test content").unwrap();

        // Test all tracing methods compile and work
        SimpleTracer::template_start(&test_path);
        SimpleTracer::template_complete(&test_path, &test_path, 100);

        let frontmatter = crate::template_types::Frontmatter::default();
        SimpleTracer::frontmatter_processed(&frontmatter);

        SimpleTracer::context_blessed(5);
        SimpleTracer::rdf_loading(&["file1.ttl".to_string()], 2, 100);
        SimpleTracer::sparql_query("SELECT * WHERE { ?s ?p ?o }", Some(10));

        SimpleTracer::file_injection(&test_path, "append", true);
        SimpleTracer::shell_hook("echo 'test'", "before", 0);
        SimpleTracer::performance("test_operation", 50);
        SimpleTracer::dry_run(&test_path, 500);
        SimpleTracer::backup_created(&test_path, &temp_dir.path().join("backup.tmpl"));
        SimpleTracer::skip_condition("skip_if", "pattern found");

        let error = crate::utils::error::Error::new("Test error");
        SimpleTracer::error(&error, "test context");
        SimpleTracer::warning("Test warning", Some("test context"));
        SimpleTracer::warning("Test warning", None);
    }

    #[test]
    fn test_tracing_environment_variables() {
        // Test different GGEN_TRACE values
        let test_values = [
            "error", "warn", "info", "debug", "trace", "1", "0", "true", "false",
        ];

        for value in &test_values {
            std::env::set_var("GGEN_TRACE", value);
            let level = SimpleTracer::trace_level();
            assert!(matches!(
                level,
                TraceLevel::Error
                    | TraceLevel::Warn
                    | TraceLevel::Info
                    | TraceLevel::Debug
                    | TraceLevel::Trace
            ));
        }
    }

    #[test]
    fn test_time_operation_macro() {
        let result = time_operation!("test_op", {
            std::thread::sleep(std::time::Duration::from_millis(2));
            42
        });
        assert_eq!(result, 42);
    }
}