various: add log messages to 'critical' functions

Most of those are not critical, I just couldn't think of a better word.

Signed-off-by: NotAShelf <raf@notashelf.dev>
Change-Id: I8689bed0470604c75dbac08b7dbd514b6a6a6964

Author: NotAShelf

watt/config.rs

@@ -76,6 +76,8 @@ impl CpusDelta {
     &self,
     state: &EvalState<'_, '_>,
   ) -> anyhow::Result<(HashMap<Arc<cpu::Cpu>, cpu::Delta>, Option<bool>)> {
+    log::debug!("evaluating CPU deltas...");
+
     let cpus = match &self.for_ {
       Some(numbers) => {
         let numbers = numbers
@@ -111,6 +113,8 @@ impl CpusDelta {
 
     let mut deltas = HashMap::with_capacity(cpus.len());
 
+    log::trace!("filtering CPUs by number: {cpus:?}");
+
     for cpu in cpus {
       let state = state.in_context(EvalContext::Cpu(&cpu));
       let mut delta = cpu::Delta::default();
@@ -251,6 +255,8 @@ impl PowersDelta {
     HashMap<Arc<power_supply::PowerSupply>, power_supply::Delta>,
     Option<String>,
   )> {
+    log::debug!("evaluating power supply deltas...");
+
     let power_supplies = match &self.for_ {
       Some(names) => {
         let names = names
@@ -282,6 +288,8 @@ impl PowersDelta {
 
     let mut deltas = HashMap::with_capacity(power_supplies.len());
 
+    log::trace!("filtering power supplies by name: {power_supplies:?}");
+
     for power_supply in power_supplies {
       let state = state.in_context(EvalContext::PowerSupply(&power_supply));
       let mut delta = power_supply::Delta::default();
@@ -638,6 +646,8 @@ impl Expression {
   ) -> anyhow::Result<Option<Expression>> {
     use Expression::*;
 
+    log::trace!("evaluating expression: {self:?}");
+
     macro_rules! try_ok {
       ($expression:expr) => {
         match $expression {
@@ -945,6 +955,8 @@ impl DaemonConfig {
     {
       let mut priorities = Vec::with_capacity(config.rules.len());
 
+      log::debug!("validating rule priorities...");
+
       for rule in &config.rules {
         if priorities.contains(&rule.priority) {
           bail!("each config rule must have a different priority")
@@ -967,6 +979,8 @@ impl DaemonConfig {
 
     config.rules.sort_by_key(|rule| rule.priority);
 
+    log::debug!("sorted {} rules by priority", config.rules.len());
+
     log::debug!("loaded config: {config:#?}");
 
     Ok(config)

watt/cpu.rs

@@ -116,9 +116,13 @@ impl Cpu {
 
     const PATH: &str = "/sys/devices/system/cpu";
 
+    log::info!("detecting CPUs...");
+
     let mut cpus = vec![];
     let cache = CpuScanCache::default();
 
+    log::debug!("scanning CPU entries in {PATH}");
+
     for entry in fs::read_dir(PATH)
       .context("failed to read CPU entries")?
       .with_context(|| format!("'{PATH}' doesn't exist, are you on linux?"))?
@@ -146,16 +150,21 @@ impl Cpu {
 
     // Fall back if sysfs iteration above fails to find any cpufreq CPUs.
     if cpus.is_empty() {
+      log::warn!("no CPUs found in sysfs, using logical CPU count fallback");
       for number in 0..num_cpus::get() as u32 {
         cpus.push(from_number(number, &cache)?);
       }
     }
 
+    log::info!("detected {} CPUs", cpus.len());
+
     Ok(cpus)
   }
 
   /// Scan CPU, tuning local copy of settings.
   fn scan(&mut self, cache: &CpuScanCache) -> anyhow::Result<()> {
+    log::debug!("scanning CPU {}", self.number);
+
     let Self { number, .. } = self;
 
     if !fs::exists(format!("/sys/devices/system/cpu/cpu{number}")) {
@@ -165,6 +174,8 @@ impl Cpu {
     self.has_cpufreq =
       fs::exists(format!("/sys/devices/system/cpu/cpu{number}/cpufreq"));
 
+    log::trace!("CPU {} has cpufreq: {}", self.number, self.has_cpufreq);
+
     if self.has_cpufreq {
       self.scan_governor()?;
       self.scan_frequency()?;
@@ -179,6 +190,8 @@ impl Cpu {
   }
 
   fn scan_governor(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning governor for CPU {}", self.number);
+
     let Self { number, .. } = *self;
 
     self.governor = fs::read(format!(
@@ -210,6 +223,8 @@ impl Cpu {
   }
 
   fn scan_frequency(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning frequency for CPU {}", self.number);
+
     let Self { number, .. } = *self;
 
     let frequency_khz = fs::read_n::<u64>(format!(
@@ -233,6 +248,8 @@ impl Cpu {
   }
 
   fn scan_epp(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning EPP for CPU {}", self.number);
+
     let Self { number, .. } = *self;
 
     self.epp = fs::read(format!(
@@ -263,6 +280,8 @@ impl Cpu {
   }
 
   fn scan_epb(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning EPB for CPU {}", self.number);
+
     let Self { number, .. } = self;
 
     self.epb = fs::read(format!(
@@ -300,6 +319,8 @@ impl Cpu {
   }
 
   fn scan_stat(&mut self, cache: &CpuScanCache) -> anyhow::Result<()> {
+    log::trace!("scanning stat for CPU {}", self.number);
+
     // OnceCell::get_or_try_init is unstable. Cope:
     let stat = match cache.stat.get() {
       Some(stat) => stat,
@@ -349,6 +370,8 @@ impl Cpu {
   }
 
   fn scan_info(&mut self, cache: &CpuScanCache) -> anyhow::Result<()> {
+    log::trace!("scanning info for CPU {}", self.number);
+
     // OnceCell::get_or_try_init is unstable. Cope:
     let info = match cache.info.get() {
       Some(stat) => stat,
@@ -436,6 +459,8 @@ impl Cpu {
 
     self.governor = Some(governor.to_owned());
 
+    log::info!("CPU {} governor set to {}", self.number, governor);
+
     Ok(())
   }
 
@@ -470,6 +495,8 @@ impl Cpu {
 
     self.epp = Some(epp.to_owned());
 
+    log::info!("CPU {} EPP set to {}", self.number, epp);
+
     Ok(())
   }
 
@@ -503,6 +530,8 @@ impl Cpu {
 
     self.epb = Some(epb.to_owned());
 
+    log::info!("CPU {} EPB set to {}", self.number, epb);
+
     Ok(())
   }
 
@@ -529,6 +558,12 @@ impl Cpu {
       )
     })?;
 
+    log::info!(
+      "CPU {} min frequency set to {} MHz",
+      self.number,
+      frequency_mhz
+    );
+
     Ok(())
   }
 
@@ -581,6 +616,12 @@ impl Cpu {
       )
     })?;
 
+    log::info!(
+      "CPU {} max frequency set to {} MHz",
+      self.number,
+      frequency_mhz
+    );
+
     Ok(())
   }
 
@@ -616,6 +657,8 @@ impl Cpu {
     on: bool,
     mut cpus: impl Iterator<Item = &'a Self>,
   ) -> anyhow::Result<()> {
+    log::info!("setting CPU turbo boost to {on}");
+
     let value_boost = match on {
       true => "1",  // boost = 1 means turbo is enabled.
       false => "0", // boost = 0 means turbo is disabled.
@@ -667,6 +710,8 @@ impl Cpu {
   }
 
   pub fn hardware_frequency_mhz_maximum() -> anyhow::Result<Option<u64>> {
+    log::trace!("reading hardware frequency limits");
+
     fs::read_n::<u64>("/sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq")
       .context("failed to read CPU hardware maximum frequency")
       .map(|x| x.map(|freq| freq / 1000))
@@ -679,6 +724,8 @@ impl Cpu {
   }
 
   pub fn turbo() -> anyhow::Result<Option<bool>> {
+    log::trace!("reading turbo boost status");
+
     if let Some(content) =
       fs::read_n::<u64>("/sys/devices/system/cpu/intel_pstate/no_turbo")
         .context("failed to read CPU turbo boost status")?

watt/lib.rs

@@ -36,5 +36,7 @@ pub fn main() -> anyhow::Result<()> {
   let config = config::DaemonConfig::load_from(cli.config.as_deref())
     .context("failed to load daemon config")?;
 
+  log::info!("starting watt daemon");
+
   system::run_daemon(config)
 }

watt/power_supply.rs

@@ -115,8 +115,12 @@ const POWER_SUPPLY_PATH: &str = "/sys/class/power_supply";
 
 impl PowerSupply {
   pub fn all() -> anyhow::Result<Vec<PowerSupply>> {
+    log::info!("detecting power supplies...");
+
     let mut power_supplies = Vec::new();
 
+    log::debug!("scanning power supplies in {POWER_SUPPLY_PATH}");
+
     for entry in fs::read_dir(POWER_SUPPLY_PATH)
       .context("failed to read power supply entries")?
       .with_context(|| {
@@ -166,10 +170,14 @@ impl PowerSupply {
       power_supplies.push(power_supply);
     }
 
+    log::info!("detected {} power supplies", power_supplies.len());
+
     Ok(power_supplies)
   }
 
   fn scan(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning power supply '{}'", self.name);
+
     if !self.path.exists() {
       bail!("{self} does not exist");
     }
@@ -189,6 +197,8 @@ impl PowerSupply {
     self.is_from_peripheral = 'is_from_peripheral: {
       let name_lower = self.name.to_lowercase();
 
+      log::trace!("power supply '{}' type: {}", self.name, self.type_);
+
       // Common peripheral battery names.
       if name_lower.contains("mouse")
         || name_lower.contains("keyboard")
@@ -281,6 +291,12 @@ impl PowerSupply {
             && self.path.join(config.path_end).exists()
         })
         .copied();
+
+      log::debug!(
+        "power supply '{}' threshold config: {:?}",
+        self.name,
+        self.threshold_config
+      );
     }
 
     Ok(())
@@ -353,6 +369,8 @@ impl PowerSupply {
   }
 
   pub fn get_available_platform_profiles() -> anyhow::Result<Vec<String>> {
+    log::trace!("reading available platform profiles");
+
     let path = "/sys/firmware/acpi/platform_profile_choices";
 
     let Some(content) = fs::read(path)
@@ -377,6 +395,8 @@ impl PowerSupply {
   ///
   /// [`The Kernel docs`]: <https://docs.kernel.org/userspace-api/sysfs-platform_profile.html>
   pub fn set_platform_profile(profile: &str) -> anyhow::Result<()> {
+    log::info!("setting platform profile to '{profile}'");
+
     let profiles = Self::get_available_platform_profiles()?;
 
     if !profiles
@@ -397,6 +417,8 @@ impl PowerSupply {
   }
 
   pub fn platform_profile() -> anyhow::Result<String> {
+    log::trace!("reading current platform profile");
+
     fs::read("/sys/firmware/acpi/platform_profile")
       .context("failed to read platform profile")?
       .context("failed to find platform profile")

watt/system.rs

@@ -207,6 +207,8 @@ impl System {
   }
 
   fn scan_temperatures(&mut self) -> anyhow::Result<()> {
+    log::debug!("scanning CPU temperatures...");
+
     const PATH: &str = "/sys/class/hwmon";
 
     let mut temperatures = HashMap::new();
@@ -414,6 +416,8 @@ impl System {
   }
 
   fn scan_load_average(&mut self) -> anyhow::Result<()> {
+    log::trace!("scanning load average");
+
     let content = fs::read("/proc/loadavg")
       .context("failed to read load average from '/proc/loadavg'")?
       .context("'/proc/loadavg' doesn't exist, are you on linux?")?;
@@ -582,6 +586,8 @@ impl System {
   /// So a return value of Some(0.3) means the battery has been
   /// discharging 30% per hour.
   fn power_supply_discharge_rate(&self) -> Option<f64> {
+    log::trace!("calculating power supply discharge rate");
+
     let mut last_charge = None;
 
     // A list of increasing charge percentages.
@@ -667,6 +673,8 @@ pub fn run_daemon(config: config::DaemonConfig) -> anyhow::Result<()> {
   let last_user_activity = Instant::now();
 
   while !cancelled.load(Ordering::SeqCst) {
+    log::debug!("starting main polling loop iteration");
+
     system.scan()?;
 
     let delay = {
@@ -875,11 +883,18 @@ pub fn run_daemon(config: config::DaemonConfig) -> anyhow::Result<()> {
         .with_context(|| format!("failed to apply delta to {cpu}"))?;
     }
 
+    log::info!("applying CPU deltas to {} CPUs", cpu_deltas.len());
+
     if let Some(turbo) = cpu_turbo {
       cpu::Cpu::set_turbo(turbo, cpu_deltas.keys().map(|arc| &**arc))
         .context("failed to set CPU turbo")?;
     }
 
+    log::info!(
+      "applying power supply deltas to {} devices",
+      power_deltas.len()
+    );
+
     for (power, delta) in power_deltas {
       delta
         .apply(&mut (*power).clone())