cli_shared/logging/

mod.rs

// SPDX-License-Identifier: Apache-2.0
//! Structured logging initialization and configuration.
//!
//! This module provides centralized logging setup using the `tracing` ecosystem.
//! It supports both human-readable and JSON output formats, configurable via
//! environment variables.
//!
//! # Configuration
//!
//! Logging is controlled via the `RUST_LOG` environment variable:
//!
//! ```bash
//! # Default logging (info level)
//! RUST_LOG=info
//!
//! # Debug level for heddle only
//! RUST_LOG=heddle=debug
//!
//! # Trace everything
//! RUST_LOG=trace
//!
//! # JSON output for machine parsing
//! RUST_LOG=info HEDDLE_LOG_FORMAT=json
//! ```

use std::io::{self, IsTerminal};
#[cfg(feature = "telemetry")]
use std::time::Duration;

mod trace;
#[cfg(feature = "telemetry")]
use opentelemetry::{KeyValue, global, trace::TracerProvider as _};
#[cfg(feature = "telemetry")]
use opentelemetry_otlp::WithExportConfig;
#[cfg(feature = "telemetry")]
use opentelemetry_sdk::{Resource, metrics::SdkMeterProvider, trace::SdkTracerProvider};
pub use trace::{CommandTrace, record_phase_span, trace_export_enabled};
use tracing::Level;
#[cfg(feature = "telemetry")]
use tracing_subscriber::filter::filter_fn;
use tracing_subscriber::{
    EnvFilter, Layer as _, fmt::format::FmtSpan, layer::SubscriberExt, util::SubscriberInitExt,
};

use crate::config::UserConfig;

fn is_truthy(val: &str) -> bool {
    matches!(
        val.to_ascii_lowercase().as_str(),
        "1" | "true" | "yes" | "on"
    )
}

#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum LogFormat {
    Text,
    Json,
}

#[derive(Debug, Clone)]
pub struct LoggingConfig {
    pub format: LogFormat,
    /// Filter level used when `RUST_LOG` is unset. Foreground CLI commands
    /// default this to `Warn`; `-v` raises to Info, `-vv` to Debug, `-vvv`
    /// to Trace; `--quiet` lowers to Error. `RUST_LOG` always overrides.
    pub default_level: Level,
    pub include_location: bool,
    pub include_thread_ids: bool,
    pub log_spans: bool,
    pub otel_service_name: Option<String>,
    pub otel_endpoint: Option<String>,
    pub otel_traces_endpoint: Option<String>,
    pub otel_metrics_endpoint: Option<String>,
}

#[derive(Debug, Default)]
pub struct LoggingGuard {
    #[cfg(feature = "telemetry")]
    tracer_provider: Option<SdkTracerProvider>,
    #[cfg(feature = "telemetry")]
    meter_provider: Option<SdkMeterProvider>,
}

impl LoggingGuard {
    pub fn shutdown(mut self) {
        self.shutdown_inner();
    }

    fn shutdown_inner(&mut self) {
        #[cfg(feature = "telemetry")]
        {
            if let Some(meter_provider) = self.meter_provider.take() {
                let _ = meter_provider.shutdown_with_timeout(Duration::from_millis(250));
            }
            if let Some(tracer_provider) = self.tracer_provider.take() {
                let _ = tracer_provider.shutdown_with_timeout(Duration::from_millis(250));
            }
            trace::set_trace_export_enabled(false);
        }
    }
}

impl Drop for LoggingGuard {
    fn drop(&mut self) {
        self.shutdown_inner();
    }
}

#[cfg(feature = "telemetry")]
#[derive(Debug, Clone)]
struct OtelConfig {
    service_name: String,
    trace_endpoint: Option<String>,
    metrics_endpoint: Option<String>,
}

impl Default for LoggingConfig {
    fn default() -> Self {
        Self {
            format: LogFormat::Text,
            default_level: Level::WARN,
            include_location: false,
            include_thread_ids: false,
            log_spans: false,
            otel_service_name: None,
            otel_endpoint: None,
            otel_traces_endpoint: None,
            otel_metrics_endpoint: None,
        }
    }
}

impl LoggingConfig {
    pub fn from_env() -> Self {
        Self::from_user_and_env(None)
    }

    pub fn from_user_and_env(user_config: Option<&UserConfig>) -> Self {
        let mut config = Self::default();

        if let Some(user_config) = user_config {
            if user_config
                .logging
                .format
                .as_deref()
                .is_some_and(|format| format.eq_ignore_ascii_case("json"))
            {
                config.format = LogFormat::Json;
            }
            config.include_location = user_config.logging.include_location;
            config.include_thread_ids = user_config.logging.include_thread_ids;
            config.log_spans = user_config.logging.log_spans;
            config.otel_service_name = user_config.logging.otel_service_name.clone();
            config.otel_endpoint = user_config.logging.otel_endpoint.clone();
            config.otel_traces_endpoint = user_config.logging.otel_traces_endpoint.clone();
            config.otel_metrics_endpoint = user_config.logging.otel_metrics_endpoint.clone();
        }

        if let Ok(format) = std::env::var("HEDDLE_LOG_FORMAT")
            && format.eq_ignore_ascii_case("json")
        {
            config.format = LogFormat::Json;
        }

        if std::env::var("HEDDLE_LOG_LOCATION")
            .map(|v| is_truthy(&v))
            .unwrap_or(false)
        {
            config.include_location = true;
        }

        if std::env::var("HEDDLE_LOG_THREADS")
            .map(|v| is_truthy(&v))
            .unwrap_or(false)
        {
            config.include_thread_ids = true;
        }

        if std::env::var("HEDDLE_LOG_SPANS")
            .map(|v| is_truthy(&v))
            .unwrap_or(false)
        {
            config.log_spans = true;
        }

        if let Ok(service_name) = std::env::var("OTEL_SERVICE_NAME") {
            config.otel_service_name = Some(service_name);
        }
        if let Ok(endpoint) = std::env::var("OTEL_EXPORTER_OTLP_ENDPOINT") {
            config.otel_endpoint = Some(endpoint);
        }
        if let Ok(endpoint) = std::env::var("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT") {
            config.otel_traces_endpoint = Some(endpoint);
        }
        if let Ok(endpoint) = std::env::var("OTEL_EXPORTER_OTLP_METRICS_ENDPOINT") {
            config.otel_metrics_endpoint = Some(endpoint);
        }

        config
    }

    pub fn with_format(mut self, format: LogFormat) -> Self {
        self.format = format;
        self
    }

    /// Map CLI `-v`/`--quiet` counts to a default log level.
    ///
    /// `quiet` wins over `verbose`; `RUST_LOG` overrides both downstream.
    /// 0 → keep current (e.g. `Warn` for foreground), 1 → Info, 2 → Debug,
    /// 3+ → Trace.
    pub fn with_verbosity(mut self, verbose: u8, quiet: bool) -> Self {
        self.default_level = if quiet {
            Level::ERROR
        } else {
            match verbose {
                0 => self.default_level,
                1 => Level::INFO,
                2 => Level::DEBUG,
                _ => Level::TRACE,
            }
        };
        self
    }

    pub fn with_location(mut self, include: bool) -> Self {
        self.include_location = include;
        self
    }

    pub fn with_thread_ids(mut self, include: bool) -> Self {
        self.include_thread_ids = include;
        self
    }

    pub fn with_spans(mut self, include: bool) -> Self {
        self.log_spans = include;
        self
    }
}

#[cfg(feature = "telemetry")]
impl OtelConfig {
    fn from_logging_config(config: &LoggingConfig) -> Self {
        Self {
            service_name: config
                .otel_service_name
                .clone()
                .unwrap_or_else(|| "heddle".to_string()),
            trace_endpoint: config
                .otel_traces_endpoint
                .clone()
                .or_else(|| signal_endpoint(config.otel_endpoint.as_deref(), "v1/traces")),
            metrics_endpoint: config
                .otel_metrics_endpoint
                .clone()
                .or_else(|| signal_endpoint(config.otel_endpoint.as_deref(), "v1/metrics")),
        }
    }

    fn enabled(&self) -> bool {
        self.trace_endpoint.is_some() || self.metrics_endpoint.is_some()
    }

    fn resource(&self) -> Resource {
        Resource::builder_empty()
            .with_attributes([KeyValue::new("service.name", self.service_name.clone())])
            .build()
    }
}

#[cfg(feature = "telemetry")]
fn signal_endpoint(base: Option<&str>, signal_path: &str) -> Option<String> {
    base.map(|endpoint| format!("{}/{signal_path}", endpoint.trim_end_matches('/')))
}

/// Initialize the global tracing subscriber.
///
/// # Example
///
/// ```rust
/// use cli_shared::logging::{LoggingConfig, init_logging};
///
/// fn main() {
///     init_logging(LoggingConfig::from_env());
///
///     tracing::info!("Logging initialized");
/// }
/// ```
pub fn init_logging(config: LoggingConfig) -> LoggingGuard {
    let env_filter = EnvFilter::try_from_default_env()
        .unwrap_or_else(|_| EnvFilter::new(level_to_filter(config.default_level)));
    let span_events = if config.log_spans {
        FmtSpan::FULL
    } else {
        FmtSpan::NONE
    };
    let telemetry = init_otel(&config);
    let registry = tracing_subscriber::registry();

    #[cfg(feature = "telemetry")]
    let init_result = match (config.format, telemetry.tracer_provider.as_ref()) {
        (LogFormat::Text, Some(provider)) => registry
            .with(
                tracing_opentelemetry::layer()
                    .with_tracer(provider.tracer(telemetry.service_name.clone()))
                    .with_filter(filter_fn(|metadata| {
                        metadata.target() == trace::TELEMETRY_TARGET
                    })),
            )
            .with(
                tracing_subscriber::fmt::layer()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_ansi(io::stderr().is_terminal())
                    .with_filter(env_filter),
            )
            .try_init(),
        (LogFormat::Text, None) => registry
            .with(
                tracing_subscriber::fmt::layer()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_ansi(io::stderr().is_terminal())
                    .with_filter(env_filter),
            )
            .try_init(),
        (LogFormat::Json, Some(provider)) => registry
            .with(
                tracing_opentelemetry::layer()
                    .with_tracer(provider.tracer(telemetry.service_name.clone()))
                    .with_filter(filter_fn(|metadata| {
                        metadata.target() == trace::TELEMETRY_TARGET
                    })),
            )
            .with(
                tracing_subscriber::fmt::layer()
                    .json()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_filter(env_filter),
            )
            .try_init(),
        (LogFormat::Json, None) => registry
            .with(
                tracing_subscriber::fmt::layer()
                    .json()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_filter(env_filter),
            )
            .try_init(),
    };

    #[cfg(not(feature = "telemetry"))]
    let init_result = match config.format {
        LogFormat::Text => registry
            .with(
                tracing_subscriber::fmt::layer()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_ansi(io::stderr().is_terminal())
                    .with_filter(env_filter),
            )
            .try_init(),
        LogFormat::Json => registry
            .with(
                tracing_subscriber::fmt::layer()
                    .json()
                    .with_writer(io::stderr)
                    .with_target(true)
                    .with_level(true)
                    .with_thread_ids(config.include_thread_ids)
                    .with_file(config.include_location)
                    .with_line_number(config.include_location)
                    .with_span_events(span_events)
                    .with_filter(env_filter),
            )
            .try_init(),
    };

    if let Err(err) = init_result {
        eprintln!("failed to initialize tracing subscriber: {err}");
    }

    telemetry.guard
}

pub fn init_logging_default() {
    let _ = init_logging(LoggingConfig::default());
}

fn level_to_filter(level: Level) -> &'static str {
    match level {
        Level::TRACE => "trace",
        Level::DEBUG => "debug",
        Level::INFO => "info",
        Level::WARN => "warn",
        Level::ERROR => "error",
    }
}

pub fn is_enabled(level: Level) -> bool {
    tracing::level_enabled!(level)
}

#[macro_export]
macro_rules! log_operation {
    ($operation:expr, $($key:ident = $value:expr),+ $(,)?) => {
        tracing::info!(
            operation = %$operation,
            $($key = %$value),+,
            "Operation executed"
        )
    };
    ($operation:expr) => {
        tracing::info!(operation = %$operation, "Operation executed")
    };
}

#[macro_export]
macro_rules! log_repo_event {
    ($event:expr, change_id = $change_id:expr $(, $key:ident = $value:expr)* $(,)?) => {
        tracing::info!(
            event = %$event,
            change_id = %$change_id,
            $($key = %$value),*,
            "Repository event"
        )
    };
}

struct TelemetryInit {
    guard: LoggingGuard,
    #[cfg(feature = "telemetry")]
    tracer_provider: Option<SdkTracerProvider>,
    #[cfg(feature = "telemetry")]
    service_name: String,
    #[cfg(all(test, feature = "telemetry"))]
    network_client_initialized: bool,
}

#[cfg(feature = "telemetry")]
fn init_otel(logging: &LoggingConfig) -> TelemetryInit {
    let config = OtelConfig::from_logging_config(logging);
    if !config.enabled() {
        return TelemetryInit {
            guard: LoggingGuard::default(),
            tracer_provider: None,
            service_name: config.service_name,
            #[cfg(all(test, feature = "telemetry"))]
            network_client_initialized: false,
        };
    }

    let resource = config.resource();
    let tracer_provider = config.trace_endpoint.as_ref().and_then(|endpoint| {
        let exporter = opentelemetry_otlp::SpanExporter::builder()
            .with_http()
            .with_endpoint(endpoint.to_string())
            .build()
            .map_err(|err| {
                eprintln!("failed to initialize OTLP trace exporter: {err}");
                err
            })
            .ok()?;
        let provider = SdkTracerProvider::builder()
            .with_resource(resource.clone())
            .with_batch_exporter(exporter)
            .build();
        global::set_tracer_provider(provider.clone());
        Some(provider)
    });
    trace::set_trace_export_enabled(tracer_provider.is_some());

    let meter_provider = config.metrics_endpoint.as_ref().and_then(|endpoint| {
        let exporter = opentelemetry_otlp::MetricExporter::builder()
            .with_http()
            .with_endpoint(endpoint.to_string())
            .build()
            .map_err(|err| {
                eprintln!("failed to initialize OTLP metric exporter: {err}");
                err
            })
            .ok()?;
        let provider = SdkMeterProvider::builder()
            .with_periodic_exporter(exporter)
            .with_resource(resource.clone())
            .build();
        global::set_meter_provider(provider.clone());
        Some(provider)
    });

    TelemetryInit {
        guard: LoggingGuard {
            tracer_provider: tracer_provider.clone(),
            meter_provider,
        },
        tracer_provider,
        service_name: config.service_name,
        #[cfg(all(test, feature = "telemetry"))]
        network_client_initialized: config.trace_endpoint.is_some()
            || config.metrics_endpoint.is_some(),
    }
}

#[cfg(not(feature = "telemetry"))]
fn init_otel(_logging: &LoggingConfig) -> TelemetryInit {
    TelemetryInit {
        guard: LoggingGuard::default(),
    }
}

#[cfg(test)]
mod tests {
    #[cfg(feature = "telemetry")]
    use opentelemetry_sdk::trace::{InMemorySpanExporter, SdkTracerProvider, SimpleSpanProcessor};

    use super::*;

    #[test]
    fn test_logging_config_default() {
        let config = LoggingConfig::default();
        assert_eq!(config.format, LogFormat::Text);
        assert!(!config.include_location);
        assert!(!config.include_thread_ids);
        assert!(!config.log_spans);
    }

    #[test]
    fn test_logging_config_builder() {
        let config = LoggingConfig::default()
            .with_format(LogFormat::Json)
            .with_location(true)
            .with_thread_ids(true)
            .with_spans(true);

        assert_eq!(config.format, LogFormat::Json);
        assert!(config.include_location);
        assert!(config.include_thread_ids);
        assert!(config.log_spans);
    }

    #[test]
    fn test_is_truthy() {
        assert!(is_truthy("1"));
        assert!(is_truthy("true"));
        assert!(is_truthy("TRUE"));
        assert!(is_truthy("True"));
        assert!(is_truthy("yes"));
        assert!(is_truthy("YES"));
        assert!(is_truthy("on"));
        assert!(is_truthy("ON"));

        assert!(!is_truthy("0"));
        assert!(!is_truthy("false"));
        assert!(!is_truthy("FALSE"));
        assert!(!is_truthy("no"));
        assert!(!is_truthy("off"));
        assert!(!is_truthy(""));
        assert!(!is_truthy("random"));
    }

    #[cfg(feature = "telemetry")]
    #[test]
    fn endpoint_gate_is_network_dormant_and_command_spans_export_when_enabled() {
        let shared = LoggingConfig {
            otel_endpoint: Some("http://collector:4318/".to_string()),
            ..LoggingConfig::default()
        };
        let resolved = OtelConfig::from_logging_config(&shared);
        assert_eq!(
            resolved.trace_endpoint.as_deref(),
            Some("http://collector:4318/v1/traces")
        );

        let telemetry = init_otel(&LoggingConfig::default());
        assert!(telemetry.tracer_provider.is_none());
        assert!(!telemetry.network_client_initialized);
        drop(telemetry);

        let exporter = InMemorySpanExporter::default();
        let provider = SdkTracerProvider::builder()
            .with_span_processor(SimpleSpanProcessor::new(exporter.clone()))
            .build();
        let subscriber = tracing_subscriber::registry()
            .with(tracing_opentelemetry::layer().with_tracer(provider.tracer("heddle-test")));
        trace::set_trace_export_enabled(true);
        tracing::subscriber::with_default(subscriber, || {
            let mut command = CommandTrace::start("status", std::time::Instant::now())
                .expect("test trace export is enabled");
            command
                .span()
                .in_scope(|| record_phase_span("status repo open", 7));
            command.finish(0);
            drop(command);
        });
        trace::set_trace_export_enabled(false);

        let spans = exporter.get_finished_spans().expect("read exported spans");
        assert_eq!(spans.len(), 2);
        let command = spans
            .iter()
            .find(|span| span.name == "heddle.command")
            .expect("command span exported");
        let phase = spans
            .iter()
            .find(|span| span.name == "heddle.phase")
            .expect("phase span exported");
        assert_eq!(phase.parent_span_id, command.span_context.span_id());
        assert!(command.attributes.iter().any(|attribute| {
            attribute.key.as_str() == "command.status" && attribute.value.to_string() == "ok"
        }));
        assert!(phase.attributes.iter().any(|attribute| {
            attribute.key.as_str() == "phase.name"
                && attribute.value.to_string() == "status repo open"
        }));
    }
}