diff --git a/rewrite/CLAUDE.md b/rewrite/CLAUDE.md index 0865606..08afa57 100644 --- a/rewrite/CLAUDE.md +++ b/rewrite/CLAUDE.md @@ -135,3 +135,4 @@ The original includes a dummy adjustment method for testing without actual displ - Unit tests for color temperature conversion - Integration tests with dummy/mock adjustment methods - Always generate a coverage report at the end of a task and write tests for any uncovered lines or branches that were not previously ignored or skipped. +- Always add logging using the internal logging function where appropriate. diff --git a/rewrite/Cargo.toml b/rewrite/Cargo.toml index 076416e..61f4467 100644 --- a/rewrite/Cargo.toml +++ b/rewrite/Cargo.toml @@ -19,6 +19,8 @@ lazy_static = "1.5" dialoguer = "0.11" signal-hook = "0.3" rust-ini = "0.21" +log = "0.4" +env_logger = "0.11" [dev-dependencies] libc = "0.2" diff --git a/rewrite/src/config_ini.rs b/rewrite/src/config_ini.rs index 00380a8..eca32c9 100644 --- a/rewrite/src/config_ini.rs +++ b/rewrite/src/config_ini.rs @@ -3,6 +3,7 @@ use crate::types::*; use ini::Ini; +use log::{debug, info, trace}; use std::path::PathBuf; /// Configuration loaded from INI file @@ -35,9 +36,12 @@ pub struct RedshiftConfig { impl RedshiftConfig { /// Find and load the INI config file from standard locations pub fn load() -> Result { + debug!("Searching for INI configuration file"); if let Some(path) = Self::find_config_file() { + info!("Found INI config file: {}", path.display()); Self::load_from_file(&path) } else { + debug!("No INI configuration file found, using defaults"); Ok(Self::default()) } } @@ -46,7 +50,9 @@ impl RedshiftConfig { pub fn find_config_file() -> Option { let paths = Self::get_config_search_paths(); + trace!("Searching for INI config in {} locations", paths.len()); for path in paths { + trace!("Checking: {}", path.display()); if path.exists() { return Some(path); } @@ -84,6 +90,7 @@ impl RedshiftConfig { /// Load config from a specific file pub fn load_from_file(path: &PathBuf) -> Result { + debug!("Loading INI config from: {}", path.display()); let ini = Ini::load_from_file(path) .map_err(|e| format!("Failed to load INI file: {}", e))?; @@ -93,9 +100,15 @@ impl RedshiftConfig { if let Some(section) = ini.section(Some("redshift")) { if let Some(val) = section.get("temp-day") { config.temp_day = val.parse().ok(); + if let Some(temp) = config.temp_day { + debug!("Loaded temp-day from INI: {}K", temp); + } } if let Some(val) = section.get("temp-night") { config.temp_night = val.parse().ok(); + if let Some(temp) = config.temp_night { + debug!("Loaded temp-night from INI: {}K", temp); + } } if let Some(val) = section.get("fade") { config.fade = match val { @@ -177,18 +190,28 @@ impl RedshiftConfig { if let Some(val) = section.get("lon") { config.manual_lon = val.parse().ok(); } + if let (Some(lat), Some(lon)) = (config.manual_lat, config.manual_lon) { + debug!("Loaded manual location from INI: {:.4}, {:.4}", lat, lon); + } } /* Parse [randr] section for gamma method settings */ if let Some(section) = ini.section(Some("randr")) { if let Some(val) = section.get("screen") { config.randr_screen = val.parse().ok(); + if let Some(screen) = config.randr_screen { + debug!("Loaded RandR screen from INI: {}", screen); + } } if let Some(val) = section.get("crtc") { config.randr_crtc = val.parse().ok(); + if let Some(crtc) = config.randr_crtc { + debug!("Loaded RandR CRTC from INI: {}", crtc); + } } } + trace!("INI configuration loaded successfully"); Ok(config) } diff --git a/rewrite/src/gamma_randr.rs b/rewrite/src/gamma_randr.rs index ddccd73..af0856d 100644 --- a/rewrite/src/gamma_randr.rs +++ b/rewrite/src/gamma_randr.rs @@ -4,6 +4,7 @@ use crate::colorramp::colorramp_fill; use crate::gamma::GammaMethod; use crate::types::ColorSetting; +use log::{debug, info, trace, warn}; use std::fmt; use x11rb::connection::Connection; use x11rb::protocol::randr; @@ -72,6 +73,13 @@ impl RandrGammaMethod { let conn = self.conn.as_ref().ok_or("Not connected to X server")?; let ramp_size = crtc_state.ramp_size as usize; + trace!( + "Setting temperature for CRTC: temp={}K, brightness={:.2}, gamma=[{:.2}, {:.2}, {:.2}], preserve={}", + setting.temperature, setting.brightness, + setting.gamma[0], setting.gamma[1], setting.gamma[2], + preserve + ); + /* Create new gamma ramps */ let mut gamma_r = vec![0u16; ramp_size]; let mut gamma_g = vec![0u16; ramp_size]; @@ -79,11 +87,13 @@ impl RandrGammaMethod { if preserve { /* Initialize from saved state */ + debug!("Preserving original gamma ramps"); gamma_r.copy_from_slice(&crtc_state.saved_ramps[0..ramp_size]); gamma_g.copy_from_slice(&crtc_state.saved_ramps[ramp_size..2 * ramp_size]); gamma_b.copy_from_slice(&crtc_state.saved_ramps[2 * ramp_size..3 * ramp_size]); } else { /* Initialize to linear (pure state) */ + trace!("Starting with linear gamma ramps"); for i in 0..ramp_size { let value = ((i as f64 / ramp_size as f64) * 65536.0) as u16; gamma_r[i] = value; @@ -95,6 +105,14 @@ impl RandrGammaMethod { /* Apply color temperature adjustment */ colorramp_fill(&mut gamma_r, &mut gamma_g, &mut gamma_b, setting); + trace!("Gamma ramp sample (first 5 values): R=[{}, {}, {}, {}, {}]", + gamma_r.get(0).unwrap_or(&0), + gamma_r.get(1).unwrap_or(&0), + gamma_r.get(2).unwrap_or(&0), + gamma_r.get(3).unwrap_or(&0), + gamma_r.get(4).unwrap_or(&0), + ); + /* Set gamma ramps */ randr::set_crtc_gamma( conn, @@ -119,11 +137,14 @@ impl Default for RandrGammaMethod { impl GammaMethod for RandrGammaMethod { fn init(&mut self) -> Result<(), String> { + debug!("Initializing RandR gamma method"); + /* Open X server connection */ let (conn, preferred_screen) = RustConnection::connect(None) .map_err(|e| format!("Failed to connect to X server: {}", e))?; self.preferred_screen = preferred_screen; + info!("Connected to X server (screen {})", preferred_screen); /* Query RandR version */ let ver_reply = randr::query_version(&conn, RANDR_VERSION_MAJOR, RANDR_VERSION_MINOR) @@ -140,6 +161,8 @@ impl GammaMethod for RandrGammaMethod { )); } + debug!("RandR version: {}.{}", ver_reply.major_version, ver_reply.minor_version); + self.conn = Some(conn); Ok(()) } @@ -148,6 +171,8 @@ impl GammaMethod for RandrGammaMethod { let conn = self.conn.as_ref().ok_or("Not initialized")?; let root = self.get_screen_root()?; + debug!("Getting screen resources"); + /* Get screen resources (list of CRTCs) */ let res_reply = randr::get_screen_resources_current(conn, root) .map_err(|e| format!("Failed to get screen resources: {}", e))? @@ -155,11 +180,12 @@ impl GammaMethod for RandrGammaMethod { .map_err(|e| format!("RANDR Get Screen Resources Current returned error: {}", e))?; let crtcs = res_reply.crtcs; + info!("Found {} CRTCs", crtcs.len()); /* Save CRTC state and gamma ramps */ - for crtc in crtcs { + for (idx, crtc) in crtcs.iter().enumerate() { /* Get gamma ramp size */ - let gamma_size_reply = randr::get_crtc_gamma_size(conn, crtc) + let gamma_size_reply = randr::get_crtc_gamma_size(conn, *crtc) .map_err(|e| format!("Failed to get CRTC gamma size: {}", e))? .reply() .map_err(|e| format!("RANDR Get CRTC Gamma Size returned error: {}", e))?; @@ -167,12 +193,14 @@ impl GammaMethod for RandrGammaMethod { let ramp_size = gamma_size_reply.size; if ramp_size == 0 { - eprintln!("Warning: CRTC has gamma ramp size 0, skipping"); + warn!("CRTC {} has gamma ramp size 0, skipping", idx); continue; } + debug!("CRTC {}: ramp_size={}", idx, ramp_size); + /* Get current gamma ramps */ - let gamma_get_reply = randr::get_crtc_gamma(conn, crtc) + let gamma_get_reply = randr::get_crtc_gamma(conn, *crtc) .map_err(|e| format!("Failed to get CRTC gamma: {}", e))? .reply() .map_err(|e| format!("RANDR Get CRTC Gamma returned error: {}", e))?; @@ -183,8 +211,10 @@ impl GammaMethod for RandrGammaMethod { saved_ramps.extend_from_slice(&gamma_get_reply.green); saved_ramps.extend_from_slice(&gamma_get_reply.blue); + trace!("CRTC {}: saved {} gamma ramp values", idx, saved_ramps.len()); + self.crtcs.push(CrtcState { - crtc, + crtc: *crtc, ramp_size, saved_ramps, }); @@ -194,6 +224,8 @@ impl GammaMethod for RandrGammaMethod { return Err("No usable CRTCs found".to_string()); } + info!("Successfully initialized {} CRTCs for gamma adjustment", self.crtcs.len()); + Ok(()) } diff --git a/rewrite/src/location.rs b/rewrite/src/location.rs index 694261b..b764468 100644 --- a/rewrite/src/location.rs +++ b/rewrite/src/location.rs @@ -2,6 +2,7 @@ /// Ported from legacy/src/location-*.c use crate::types::Location; +use log::{debug, error, info, trace}; use std::sync::{Arc, Mutex}; use std::thread; use tokio::sync::oneshot; @@ -138,6 +139,7 @@ impl LocationProvider for GeoClue2LocationProvider { } fn start(&mut self) -> Result<(), String> { + debug!("Starting GeoClue2 location provider"); let location = Arc::clone(&self.location); let error = Arc::clone(&self.error); let (shutdown_tx, shutdown_rx) = oneshot::channel(); @@ -147,7 +149,7 @@ impl LocationProvider for GeoClue2LocationProvider { let rt = tokio::runtime::Runtime::new().expect("Failed to create tokio runtime"); rt.block_on(async move { if let Err(e) = geoclue2_async_task(location.clone(), error.clone(), shutdown_rx).await { - eprintln!("GeoClue2 error: {}", e); + error!("GeoClue2 error: {}", e); let mut err = error.lock().unwrap(); *err = Some(format!("GeoClue2 error: {}", e)); } @@ -158,6 +160,7 @@ impl LocationProvider for GeoClue2LocationProvider { self.shutdown_tx = Some(shutdown_tx); // Wait a moment for initial location + debug!("Waiting for initial location from GeoClue2"); thread::sleep(std::time::Duration::from_millis(500)); Ok(()) @@ -263,13 +266,13 @@ async fn geoclue2_async_task( // Get GeoClue2 Manager let manager = ManagerProxy::new(&conn).await?; - eprintln!("Connected to GeoClue2 Manager"); + debug!("Connected to GeoClue2 Manager"); // Get client path let client_path = manager.get_client().await.map_err(|e| { format!("Failed to get GeoClue2 client: {}. Make sure location services are enabled and Redshift has permission to access location.", e) })?; - eprintln!("Got GeoClue2 client path: {:?}", client_path); + debug!("Got GeoClue2 client path: {:?}", client_path); // Create client proxy let client = ClientProxy::builder(&conn) @@ -279,19 +282,19 @@ async fn geoclue2_async_task( // Set desktop ID if let Err(e) = client.set_desktop_id("redshift").await { - eprintln!("Warning: Could not set desktop ID: {}", e); + debug!("Could not set desktop ID: {}", e); } // Set distance threshold (50km) if let Err(e) = client.set_distance_threshold(50000).await { - eprintln!("Warning: Could not set distance threshold: {}", e); + debug!("Could not set distance threshold: {}", e); } // Subscribe to location updates let mut location_stream = client.receive_location_updated().await?; // Start the client - eprintln!("Starting GeoClue2 client..."); + debug!("Starting GeoClue2 client..."); if let Err(e) = client.start().await { let err_str = e.to_string(); if err_str.contains("AccessDenied") || err_str.contains("org.freedesktop.DBus.Error.AccessDenied") { @@ -300,12 +303,12 @@ async fn geoclue2_async_task( return Err(format!("Failed to start GeoClue2 client: {}", err_str).into()); } } - eprintln!("GeoClue2 client started, waiting for location updates..."); + debug!("GeoClue2 client started, waiting for location updates..."); // Try to get initial location from Location property if let Ok(loc_path) = client.location().await { if loc_path.as_str() != "/" { - eprintln!("Got initial location path: {:?}", loc_path); + debug!("Got initial location path: {:?}", loc_path); let geo_location_result = GeoLocationProxy::builder(&conn) .path(&loc_path) .unwrap() @@ -319,7 +322,7 @@ async fn geoclue2_async_task( lat: lat as f32, lon: lon as f32, }); - eprintln!("Initial location: {:.2}, {:.2}", lat, lon); + info!("Initial location from GeoClue2: {:.2}, {:.2}", lat, lon); } } } @@ -348,10 +351,12 @@ async fn geoclue2_async_task( lon: lon as f32, }); - eprintln!("Location updated: {:.2}, {:.2}", lat, lon); + info!("Location updated from GeoClue2: {:.2}, {:.2}", lat, lon); + trace!("New location path: {:?}", new_location_path); } _ = &mut shutdown_rx => { // Shutdown requested + debug!("GeoClue2 shutdown requested"); let _ = client.stop().await; return Ok(()); } diff --git a/rewrite/src/main.rs b/rewrite/src/main.rs index aefbe88..0c00751 100644 --- a/rewrite/src/main.rs +++ b/rewrite/src/main.rs @@ -11,12 +11,13 @@ mod signals; mod solar; mod types; -use clap::{Parser, ValueEnum}; +use clap::{ArgAction, Parser, ValueEnum}; use config::{Config, LocationSource}; -use gamma::{DummyGammaMethod, GammaMethod}; +use gamma::GammaMethod; use gamma_guard::GammaRestoreGuard; use gamma_randr::RandrGammaMethod; -use location::{GeoClue2LocationProvider, LocationProvider, ManualLocationProvider}; +use location::{GeoClue2LocationProvider, LocationProvider}; +use log::{debug, info, trace}; use std::time::{Duration, SystemTime, UNIX_EPOCH}; use types::*; @@ -30,7 +31,6 @@ const FADE_LENGTH: i32 = 40; #[derive(Debug, Clone, Copy, ValueEnum)] enum GammaMethodChoice { Randr, - Dummy, } #[derive(Parser, Debug)] @@ -57,9 +57,9 @@ struct Args { #[arg(short = 'p', long)] print: bool, - /// Verbose output - #[arg(short, long)] - verbose: bool, + /// Verbose output (can be repeated: -v=info, -vv=debug, -vvv=trace) + #[arg(short, long, action = ArgAction::Count)] + verbose: u8, /// Day temperature (default: 6500K) #[arg(short = 't', long, default_value = "6500")] @@ -249,12 +249,12 @@ fn determine_location_with_ini( args: &Args, ini_config: &config_ini::RedshiftConfig, ) -> Result<(Location, Config), Box> { + debug!("Determining location using priority system"); + // Priority 1: Command-line argument if let Some(loc_str) = &args.location { let loc = parse_location(loc_str)?; - if args.verbose { - println!("Using location from command-line: {:.4}, {:.4}", loc.lat, loc.lon); - } + info!("Using location from command-line: {:.4}, {:.4}", loc.lat, loc.lon); // Load config for other settings let mut config = Config::load().unwrap_or_default(); @@ -271,11 +271,9 @@ fn determine_location_with_ini( if should_save { config.set_location(loc, LocationSource::Manual, None); config.save().ok(); // Ignore save errors - if args.verbose { - println!("Location saved to configuration file."); - } - } else if args.verbose { - println!("Location will not be saved (session only)."); + info!("Location saved to configuration file"); + } else { + debug!("Location will not be saved (session only)"); } } @@ -287,22 +285,16 @@ fn determine_location_with_ini( // Priority 2: INI config file manual location if let Some(ini_loc) = ini_config.get_manual_location() { - if args.verbose { - println!("Using location from INI config: {:.4}, {:.4}", ini_loc.lat, ini_loc.lon); - } + info!("Using location from INI config: {:.4}, {:.4}", ini_loc.lat, ini_loc.lon); return Ok((ini_loc, config)); } // Priority 3: Try GeoClue2 if it's time for daily check if config.should_check_geoclue() { - if args.verbose { - eprintln!("Checking for automatic location via GeoClue2..."); - } + info!("Checking for automatic location via GeoClue2..."); - if let Ok(loc) = try_geoclue2(args.verbose) { - if args.verbose { - println!("Got location from GeoClue2: {:.4}, {:.4}", loc.lat, loc.lon); - } + if let Ok(loc) = try_geoclue2() { + info!("Got location from GeoClue2: {:.4}, {:.4}", loc.lat, loc.lon); config.set_location(loc, LocationSource::GeoClue2, None); config.update_geoclue_check(); @@ -318,20 +310,18 @@ fn determine_location_with_ini( // Priority 4: Use saved TOML configuration if let Some(saved_loc) = config.get_location() { - if args.verbose { - let source_name = config.location.as_ref().map(|l| match l.source { - LocationSource::Manual => "manual entry", - LocationSource::Interactive => "interactive selection", - LocationSource::GeoClue2 => "GeoClue2", - }).unwrap_or("unknown"); + let source_name = config.location.as_ref().map(|l| match l.source { + LocationSource::Manual => "manual entry", + LocationSource::Interactive => "interactive selection", + LocationSource::GeoClue2 => "GeoClue2", + }).unwrap_or("unknown"); - if let Some(ref city) = config.location.as_ref().and_then(|l| l.city_name.as_ref()) { - println!("Using saved location for {}: {:.4}, {:.4} (from {})", - city, saved_loc.lat, saved_loc.lon, source_name); - } else { - println!("Using saved location: {:.4}, {:.4} (from {})", - saved_loc.lat, saved_loc.lon, source_name); - } + if let Some(ref city) = config.location.as_ref().and_then(|l| l.city_name.as_ref()) { + info!("Using saved location for {}: {:.4}, {:.4} (from {})", + city, saved_loc.lat, saved_loc.lon, source_name); + } else { + info!("Using saved location: {:.4}, {:.4} (from {})", + saved_loc.lat, saved_loc.lon, source_name); } return Ok((saved_loc, config)); @@ -355,15 +345,13 @@ fn determine_location_with_ini( } /// Try to get location from GeoClue2 -fn try_geoclue2(verbose: bool) -> Result { +fn try_geoclue2() -> Result { let mut provider = GeoClue2LocationProvider::new(); provider.init()?; provider.start()?; // Wait for location - if verbose { - eprintln!("Waiting for location from GeoClue2..."); - } + debug!("Waiting for location from GeoClue2..."); std::thread::sleep(Duration::from_secs(5)); provider.get_location() @@ -464,6 +452,25 @@ fn build_transition_scheme( fn main() -> Result<(), Box> { let mut args = Args::parse(); + /* Initialize logger based on verbosity level */ + let log_level = match args.verbose { + 0 => log::LevelFilter::Warn, + 1 => log::LevelFilter::Info, + 2 => log::LevelFilter::Debug, + _ => log::LevelFilter::Trace, + }; + + env_logger::Builder::from_default_env() + .filter_level(log_level) + .format_timestamp(if args.verbose >= 2 { + Some(env_logger::fmt::TimestampPrecision::Millis) + } else { + Some(env_logger::fmt::TimestampPrecision::Seconds) + }) + .init(); + + debug!("Logger initialized at level: {:?}", log_level); + /* Install signal handlers for graceful shutdown and mode toggling */ signals::install_handlers()?; @@ -501,9 +508,9 @@ fn main() -> Result<(), Box> { /* Set up gamma method */ let mut gamma_method: Box = match args.method { GammaMethodChoice::Randr => Box::new(RandrGammaMethod::new()), - GammaMethodChoice::Dummy => Box::new(DummyGammaMethod::new()), }; + info!("Initializing gamma method: {}", gamma_method.name()); gamma_method.init()?; gamma_method.start()?; @@ -539,9 +546,15 @@ fn main() -> Result<(), Box> { let mut gamma_guard = GammaRestoreGuard::new(gamma_method.as_mut()); /* Apply color temperature */ - if args.verbose { - println!("Period: {}", period.name()); - } + info!("Period: {}", period.name()); + debug!( + "Color temperature: {}K, Brightness: {:.2}, Gamma: {:.2}/{:.2}/{:.2}", + color_setting.temperature, + color_setting.brightness, + color_setting.gamma[0], + color_setting.gamma[1], + color_setting.gamma[2] + ); gamma_guard.get_mut().set_temperature(&color_setting, false)?; @@ -552,7 +565,7 @@ fn main() -> Result<(), Box> { } /* Continual mode - continuously adjust color temperature */ - run_continual_mode(&location, &scheme, &mut gamma_guard, args.verbose)?; + run_continual_mode(&location, &scheme, &mut gamma_guard)?; Ok(()) } @@ -565,7 +578,6 @@ fn run_continual_mode( location: &Location, scheme: &TransitionScheme, gamma_guard: &mut GammaRestoreGuard, - verbose: bool, ) -> Result<(), Box> { /* Fade parameters */ let mut fade_length: i32 = 0; @@ -583,28 +595,26 @@ fn run_continual_mode( let mut prev_disabled = true; /* Start as true to trigger initial status print */ let mut done = false; /* Set to true when starting shutdown fade */ - if verbose { - println!("Color temperature: {}K", interp.temperature); - println!("Brightness: {:.2}", interp.brightness); - } + debug!("Starting continual mode loop"); + debug!("Initial color temperature: {}K, Brightness: {:.2}", interp.temperature, interp.brightness); /* Continuously adjust color temperature */ loop { /* Check for toggle signal (SIGUSR1) */ if signals::check_toggle() && !done { disabled = !disabled; - if verbose { - println!("Status: {}", if disabled { "Disabled" } else { "Enabled" }); - } + info!("Status: {}", if disabled { "Disabled" } else { "Enabled" }); } /* Check for exit signal (SIGINT/SIGTERM) */ if signals::is_exiting() { if done { /* Second signal during fade - stop immediately */ + debug!("Second exit signal received, stopping immediately"); break; } else { /* First signal - start shutdown fade */ + info!("Exit signal received, starting shutdown fade"); done = true; disabled = true; signals::clear_exiting(); @@ -612,8 +622,8 @@ fn run_continual_mode( } /* Print status change */ - if verbose && disabled != prev_disabled { - println!("Status: {}", if disabled { "Disabled" } else { "Enabled" }); + if disabled != prev_disabled { + info!("Status: {}", if disabled { "Disabled" } else { "Enabled" }); } prev_disabled = disabled; @@ -634,6 +644,7 @@ fn run_continual_mode( /* Current angular elevation of the sun */ let elevation = solar::solar_elevation(now, location.lat as f64, location.lon as f64); + trace!("Solar elevation: {:.2}°", elevation); /* Determine period and transition progress */ let period = if elevation >= scheme.high { @@ -653,13 +664,14 @@ fn run_continual_mode( /* Print period if it changed during this update, or if we are in the transition period. In transition we print the progress, so we always print it in that case. */ - if verbose && (period != prev_period || period == Period::Transition) { + if period != prev_period || period == Period::Transition { match period { Period::Transition => { - println!("Period: Transition ({:.1}%)", transition_prog * 100.0); + info!("Period: Transition ({:.1}%)", transition_prog * 100.0); + debug!("Transition progress: {:.3} (elevation: {:.2}°)", transition_prog, elevation); } _ => { - println!("Period: {}", period.name()); + info!("Period: {}", period.name()); } } } @@ -672,6 +684,7 @@ fn run_continual_mode( if (fade_length == 0 && color_setting_diff_is_major(&interp, &target_interp)) || (fade_length != 0 && color_setting_diff_is_major(&target_interp, &prev_target_interp)) { + debug!("Starting fade: {} steps", FADE_LENGTH); fade_length = FADE_LENGTH; fade_time = 0; fade_start_interp = interp; @@ -684,8 +697,10 @@ fn run_continual_mode( let alpha = ease_fade(frac).max(0.0).min(1.0); interpolate_color_settings(&fade_start_interp, &target_interp, alpha, &mut interp); + trace!("Fade progress: {}/{} (alpha: {:.3})", fade_time, fade_length, alpha); if fade_time > fade_length { + debug!("Fade complete"); fade_time = 0; fade_length = 0; } @@ -693,13 +708,11 @@ fn run_continual_mode( interp = target_interp; } - if verbose { - if prev_target_interp.temperature != target_interp.temperature { - println!("Color temperature: {}K", target_interp.temperature); - } - if prev_target_interp.brightness != target_interp.brightness { - println!("Brightness: {:.2}", target_interp.brightness); - } + if prev_target_interp.temperature != target_interp.temperature { + info!("Color temperature: {}K", target_interp.temperature); + } + if prev_target_interp.brightness != target_interp.brightness { + debug!("Brightness: {:.2}", target_interp.brightness); } /* Adjust temperature */ diff --git a/rewrite/tests/logging_tests.rs b/rewrite/tests/logging_tests.rs new file mode 100644 index 0000000..092aa21 --- /dev/null +++ b/rewrite/tests/logging_tests.rs @@ -0,0 +1,259 @@ +/// Tests for logging functionality and verbosity levels + +use std::process::Command; + +#[test] +fn test_no_verbose_flag_shows_minimal_output() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // With no verbose flag, should not see DEBUG, INFO, or TRACE logs + assert!(!stderr.contains("DEBUG"), "No verbose flag should not show DEBUG logs"); + assert!(!stderr.contains("INFO"), "No verbose flag should not show INFO logs"); + assert!(!stderr.contains("TRACE"), "No verbose flag should not show TRACE logs"); +} + +#[test] +fn test_single_v_shows_info_logs() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-v"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // With -v, should see INFO logs + assert!(stderr.contains("INFO"), "Single -v should show INFO logs"); + assert!(stderr.contains("Using location from command-line"), "Should log location source"); + assert!(stderr.contains("Initializing gamma method"), "Should log gamma initialization"); + + // Should not see DEBUG or TRACE + assert!(!stderr.contains("DEBUG"), "Single -v should not show DEBUG logs"); + assert!(!stderr.contains("TRACE"), "Single -v should not show TRACE logs"); +} + +#[test] +fn test_double_v_shows_debug_logs() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // With -vv, should see both INFO and DEBUG logs + assert!(stderr.contains("INFO"), "Double -v should show INFO logs"); + assert!(stderr.contains("DEBUG"), "Double -v should show DEBUG logs"); + assert!(stderr.contains("Logger initialized at level: Debug"), "Should log logger initialization"); + assert!(stderr.contains("CRTC"), "Should log CRTC details"); + + // Should not see TRACE + assert!(!stderr.contains("TRACE"), "Double -v should not show TRACE logs"); +} + +#[test] +fn test_triple_v_shows_trace_logs() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vvv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // With -vvv, should see INFO, DEBUG, and TRACE logs + assert!(stderr.contains("INFO"), "Triple -v should show INFO logs"); + assert!(stderr.contains("DEBUG"), "Triple -v should show DEBUG logs"); + assert!(stderr.contains("TRACE"), "Triple -v should show TRACE logs"); + assert!(stderr.contains("Logger initialized at level: Trace"), "Should log trace level"); + assert!(stderr.contains("Searching for INI config"), "Should log config search"); + assert!(stderr.contains("saved") && stderr.contains("gamma ramp values"), "Should log gamma ramp details"); +} + +#[test] +fn test_location_logging_from_cli() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "48.8566:2.3522", "-p", "-v"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Using location from command-line"), "Should log location source"); + assert!(stderr.contains("48.8566"), "Should log latitude"); + assert!(stderr.contains("2.3522"), "Should log longitude"); +} + +#[test] +fn test_gamma_initialization_logging() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-v"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Initializing gamma method: randr"), "Should log gamma method"); + assert!(stderr.contains("Connected to X server"), "Should log X connection"); + assert!(stderr.contains("Found") && stderr.contains("CRTCs"), "Should log CRTC count"); + assert!(stderr.contains("Successfully initialized") && stderr.contains("CRTCs"), "Should log success"); +} + +#[test] +fn test_debug_logging_shows_randr_version() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("RandR version:"), "Should log RandR version at debug level"); + assert!(stderr.contains("Getting screen resources"), "Should log screen resource gathering"); +} + +#[test] +fn test_trace_logging_shows_gamma_ramp_details() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vvv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("saved") && stderr.contains("gamma ramp values"), + "Should log saved gamma ramp count at trace level"); + // Note: "Setting temperature for CRTC" only appears in continual mode, not print mode + // In print mode, we can check for CRTC details + assert!(stderr.contains("CRTC") && stderr.contains("saved"), + "Should log CRTC details at trace level"); +} + +#[test] +fn test_config_search_logging() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Searching for INI configuration file"), + "Should log config search at debug level"); +} + +#[test] +fn test_trace_shows_config_search_paths() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vvv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Checking:"), "Should show individual config paths at trace level"); +} + +#[test] +fn test_period_logging() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-v"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + let stdout = String::from_utf8_lossy(&output.stdout); + let combined = format!("{}{}", stderr, stdout); + + // Should log the period (Night, Daytime, or Transition) + assert!(combined.contains("Period:"), "Should log current period"); +} + +#[test] +fn test_color_temperature_logging_at_debug() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stdout = String::from_utf8_lossy(&output.stdout); + let stderr = String::from_utf8_lossy(&output.stderr); + let combined = format!("{}{}", stderr, stdout); + + // At debug level, should see color settings in DEBUG logs or output + assert!(combined.contains("Color temperature:"), + "Should show color temperature"); + assert!(combined.contains("Brightness:"), "Should show brightness"); + assert!(combined.contains("Gamma:"), "Should show gamma values"); +} + +#[test] +fn test_timestamp_precision_at_debug_level() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // At -vv (debug), timestamps should have millisecond precision + // Format: [2025-10-07T23:35:25.071Z DEBUG ...] + assert!(stderr.contains("Z DEBUG"), "Debug level should have timestamps"); + // Check for milliseconds (the .XXX part before Z) + let has_millis = stderr.lines() + .filter(|line| line.contains("DEBUG")) + .any(|line| { + // Look for pattern like .NNN] + line.contains('.') && line.chars() + .skip_while(|&c| c != '.') + .skip(1) + .take(3) + .all(|c| c.is_ascii_digit()) + }); + assert!(has_millis, "Debug timestamps should include milliseconds"); +} + +#[test] +fn test_verbosity_count_increments() { + // Test that -vvvv (more than 3) still works and maps to Trace + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vvvv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + // Should still show Trace level (max level) + assert!(stderr.contains("Logger initialized at level: Trace"), + "More than 3 -v flags should still map to Trace"); + assert!(stderr.contains("TRACE"), "Should show TRACE logs"); +} + +#[test] +fn test_logger_initialization_logging() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Logger initialized at level:"), + "Should log logger initialization at debug level"); +} + +#[test] +fn test_location_determination_logging() { + let output = Command::new("cargo") + .args(&["run", "--", "-l", "40:-74", "-p", "-vv"]) + .output() + .expect("Failed to execute command"); + + let stderr = String::from_utf8_lossy(&output.stderr); + + assert!(stderr.contains("Determining location using priority system"), + "Should log location determination at debug level"); +}