Logging and minor code improvements

Cargo.toml

@@ -31,7 +31,8 @@ tonic-types = {version="0.11.0"}
 tonic-reflection = {version="0.11.0"}
 tower = {version = "0.4"}
 tracing = "0.1"
-tracing-subscriber = {version = "0.3"}
+tracing-subscriber = {version = "0.3", features = ["env-filter", "tracing-log", "time", "local-time"]}
+tracing-journald = {version =" 0.2.0"}
 serde = { version = "1.0.202", features = ["derive"]}
 serde_json = "1.0.120"
 x509-parser = { version = "0.16" }

nixos/modules/admin.nix

@@ -23,6 +23,7 @@ in
 {
   options.givc.admin = {
     enable = mkEnableOption "Enable givc-admin module.";
+    debug = mkEnableOption "Enable givc-admin debug logging.";
 
     name = mkOption {
       description = "Host name (without domain).";
@@ -134,6 +135,10 @@ in
           "CA_CERT" = "${cfg.tls.caCertPath}";
           "HOST_CERT" = "${cfg.tls.certPath}";
           "HOST_KEY" = "${cfg.tls.keyPath}";
+        }
+        // attrsets.optionalAttrs cfg.debug {
+          "RUST_BACKTRACE" = "1";
+          "GIVC_LOG" = "debug";
         };
     };
     networking.firewall.allowedTCPPorts =

nixos/tests/admin.nix

@@ -44,6 +44,7 @@ in
               ];
               givc.admin = {
                 enable = true;
+                debug = true;
                 name = "admin-vm";
                 addr = addrs.adminvm;
                 port = "9001";

src/admin/registry.rs

@@ -37,7 +37,7 @@ impl Registry {
         self.send_event(event)
     }
 
-    pub fn deregister(&self, name: &String) -> anyhow::Result<()> {
+    pub fn deregister(&self, name: &str) -> anyhow::Result<()> {
         let mut state = self.map.lock().unwrap();
         match state.remove(name) {
             Some(entry) => {
@@ -49,19 +49,19 @@ impl Registry {
         }
     }
 
-    pub fn by_name(&self, name: &String) -> anyhow::Result<RegistryEntry> {
+    pub fn by_name(&self, name: &str) -> anyhow::Result<RegistryEntry> {
         let state = self.map.lock().unwrap();
         state
             .get(name)
             .cloned()
             .ok_or_else(|| anyhow!("Service {name} not registered"))
     }
 
-    pub fn find_names(&self, name: &String) -> anyhow::Result<Vec<String>> {
+    pub fn find_names(&self, name: &str) -> anyhow::Result<Vec<String>> {
         let state = self.map.lock().unwrap();
         let list: Vec<String> = state
             .keys()
-            .filter(|x| x.starts_with(name.as_str()))
+            .filter(|x| x.starts_with(name))
             .cloned()
             .collect();
         if list.len() == 0 {
@@ -85,12 +85,12 @@ impl Registry {
         }
     }
 
-    pub fn contains(&self, name: &String) -> bool {
+    pub fn contains(&self, name: &str) -> bool {
         let state = self.map.lock().unwrap();
         state.contains_key(name)
     }
 
-    pub fn create_unique_entry_name(&self, name: &String) -> String {
+    pub fn create_unique_entry_name(&self, name: &str) -> String {
         let state = self.map.lock().unwrap();
         let mut counter = 0;
         loop {
@@ -107,7 +107,7 @@ impl Registry {
         state.values().filter(|x| x.watch).cloned().collect()
     }
 
-    pub fn update_state(&self, name: &String, status: UnitStatus) -> anyhow::Result<()> {
+    pub fn update_state(&self, name: &str, status: UnitStatus) -> anyhow::Result<()> {
         let mut state = self.map.lock().unwrap();
         state
             .get_mut(name)

src/admin/server.rs

@@ -7,7 +7,7 @@ use std::pin::Pin;
 use std::sync::Arc;
 use std::time::Duration;
 use tonic::{Code, Response, Status};
-use tracing::{error, info};
+use tracing::{debug, error, info};
 
 pub use pb::admin_service_server::AdminServiceServer;
 
@@ -177,7 +177,7 @@ impl AdminServiceImpl {
     async fn monitor_routine(&self) -> anyhow::Result<()> {
         let watch_list = self.registry.watch_list();
         for entry in watch_list {
-            info!("Monitoring {}...", &entry.name);
+            debug!("Monitoring {}...", &entry.name);
             match self.get_remote_status(&entry).await {
                 Err(err) => {
                     error!(
@@ -199,7 +199,7 @@ impl AdminServiceImpl {
                         )
                     };
 
-                    info!("Status of {} is {:#?} (updated)", &entry.name, status);
+                    debug!("Status of {} is {:#?} (updated)", &entry.name, status);
                     // We have immutable copy of entry here, but need update _in registry_ copy
                     self.registry.update_state(&entry.name, status)?;
 
@@ -219,7 +219,6 @@ impl AdminServiceImpl {
         watch.tick().await; // First tick fires instantly
         loop {
             watch.tick().await;
-            info!("Monitoring...");
             if let Err(err) = self.monitor_routine().await {
                 error!("Error during watch: {}", err);
             }

src/bin/givc-admin.rs

@@ -5,7 +5,7 @@ use givc_common::pb::reflection::ADMIN_DESCRIPTOR;
 use std::net::SocketAddr;
 use std::path::PathBuf;
 use tonic::transport::Server;
-use tracing::info;
+use tracing::debug;
 
 #[derive(Debug, Parser)] // requires `derive` feature
 #[command(name = "givc-admin")]
@@ -39,10 +39,10 @@ struct Cli {
 
 #[tokio::main]
 async fn main() -> std::result::Result<(), Box<dyn std::error::Error>> {
-    givc::trace_init();
+    givc::trace_init()?;
 
     let cli = Cli::parse();
-    info!("CLI is {:#?}", cli);
+    debug!("CLI is {:#?}", cli);
 
     let addr = SocketAddr::new(cli.addr.parse().unwrap(), cli.port);
 

src/bin/givc-agent.rs

@@ -60,7 +60,7 @@ struct Cli {
 
 #[tokio::main]
 async fn main() -> std::result::Result<(), Box<dyn std::error::Error>> {
-    givc::trace_init();
+    givc::trace_init()?;
 
     let cli = Cli::parse();
     info!("CLI is {:#?}", cli);

src/bin/givc-cli.rs

@@ -110,7 +110,7 @@ async fn test_subcommands(test: Test, admin: AdminClient) -> anyhow::Result<()>
 
 #[tokio::main]
 async fn main() -> std::result::Result<(), Box<dyn std::error::Error>> {
-    givc::trace_init();
+    givc::trace_init()?;
 
     let cli = Cli::parse();
     info!("CLI is {:#?}", cli);

src/lib.rs

@@ -9,6 +9,40 @@ pub mod pb {
 pub use givc_client::endpoint;
 pub use givc_common::types;
 
-pub fn trace_init() {
-    tracing_subscriber::fmt::init();
+pub fn trace_init() -> anyhow::Result<()> {
+    use std::env;
+    use tracing::Level;
+    use tracing_subscriber::{filter::LevelFilter, layer::SubscriberExt, EnvFilter, Layer};
+
+    let env_filter =
+        EnvFilter::try_from_env("GIVC_LOG").unwrap_or_else(|_| EnvFilter::from("info"));
+    let is_debug_log_level = env_filter
+        .max_level_hint()
+        .map_or_else(|| false, |level| level >= Level::DEBUG);
+
+    let stdout = tracing_subscriber::fmt::layer()
+        .with_target(is_debug_log_level)
+        .with_file(is_debug_log_level)
+        .with_line_number(is_debug_log_level)
+        .with_thread_ids(is_debug_log_level);
+
+    let stdout = if is_debug_log_level {
+        stdout.pretty().boxed()
+    } else {
+        stdout.boxed()
+    };
+
+    // enable journald logging only on release to avoid log spam on dev machines
+    let journald = match env::var("INVOCATION_ID") {
+        Err(_) => None,
+        Ok(_) => tracing_journald::layer().ok(),
+    };
+
+    let subscriber = tracing_subscriber::registry()
+        .with(journald.with_filter(LevelFilter::INFO))
+        .with(stdout.with_filter(env_filter));
+
+    tracing::subscriber::set_global_default(subscriber)
+        .expect("tracing shouldn't already have been set up");
+    Ok(())
 }