feat: logging in credential manager

Cargo.toml

@@ -14,3 +14,6 @@ keyring = { version = "3.6.1", features = ["apple-native", "windows-native", "sy
 rpassword = "7.3.1"
 rusqlite = { version = "0.32.1", features = ["bundled"] }
 thiserror = "2.0.3"
+tracing = "0.1.40"
+tracing-appender = "0.2.3"
+tracing-subscriber = "0.3.18"

src/credential_manager.rs

@@ -5,6 +5,7 @@ use app_dirs2::{AppDataType, AppInfo, app_root};
 use anyhow::{Result, Context};
 use keyring::Entry;
 use rusqlite::Connection;
+use tracing::{debug, info};
 
 #[derive(Debug)]
 struct DatabaseCredential {
@@ -13,6 +14,7 @@ struct DatabaseCredential {
     totp_nonce: Option<Vec<u8>>
 }
 
+#[derive(Debug)]
 pub struct Credential {
     pub user: String,
     pub password: String,
@@ -28,25 +30,33 @@ impl Credential {
         }
     }
 
+    #[tracing::instrument]
     pub fn totp(&self) -> Option<String> {
         match self.totp_command.clone() {
             Some(totp_command) => {
+                info!("TOTP command found.");
+
                 let parts = totp_command.split(" ").collect::<Vec<&str>>();
                 let command = parts.first()?.to_string();
                 let args = totp_command[command.len()..].to_string();
 
+                debug!("Executing TOTP command.");
                 let output = Command::new(command)
                      .arg(args)
                      .output()
                      .expect("failed to execute process");
 
                 Some(String::from_utf8_lossy(&output.stdout).trim().to_string())
             },
-            None => None
+            None => {
+                info!("No TOTP command found.");
+                None
+            }
         }
     }
 }
 
+#[derive(Debug)]
 pub struct CredentialManager {
     connection: Connection,
     entry_cache: HashMap<(String, String), Entry>
@@ -60,6 +70,7 @@ impl CredentialManager {
         })
     }
 
+    #[tracing::instrument]
     fn get_connection() -> Result<Connection> {
         // Get the path to the credential database
         let mut path = app_root(AppDataType::UserConfig, &AppInfo{
@@ -71,15 +82,19 @@ impl CredentialManager {
 
         // Create the folder if it doesn't already exist.
         if !sqlite_path.parent().context("No parent")?.exists(){
+            debug!("Creating directories for sqlite database.");
             create_dir_all(sqlite_path.parent().context("No parent")?)?;
         }
 
+        debug!("Creating sqlite database connection.");
         Ok(Connection::open(sqlite_path)?)
     }
 
+    #[tracing::instrument]
     fn get_database_credential_iter(&self, url: &str) -> Result<Vec<DatabaseCredential>> {
         let database = self.get_database()?;
 
+        info!("Selecting rows from user database.");
         let mut stmt: rusqlite::Statement<'_> = database.prepare(
             "SELECT user, totp_command_encrypted, totp_nonce FROM Credentials WHERE url=:url;")?;
         let rows: Vec<DatabaseCredential> = stmt.query_map(&[(":url", url)], |row| {
@@ -89,11 +104,15 @@ impl CredentialManager {
                 totp_nonce: row.get(2)?
             })
         })?.filter_map(|r| r.ok()).collect::<Vec<DatabaseCredential>>().try_into()?;
-
+
+        debug!(count=rows.len(), "Found user rows.");
         Ok(rows)
     }
 
+    #[tracing::instrument]
     fn get_database(&self) -> Result<&Connection> {
+        info!("Creating Credentials table in user database.");
+
         let conn = &self.connection;
         conn.execute(
             "CREATE TABLE IF NOT EXISTS Credentials (
@@ -109,15 +128,21 @@ impl CredentialManager {
         Ok(conn)
     }
 
+    #[tracing::instrument]
     fn get_entry(&mut self, url: &str, user: &str) -> Result<&Entry>{
         if !self.entry_cache.contains_key(&(url.to_string(), user.to_string())) {
+            debug!(user=user, url=url, "Entry did not exist in cache.");
+
+            info!("Creating entry.");
             let entry = Entry::new(url, user)?;
             self.entry_cache.insert((url.to_string(), user.to_string()), entry);
         }
 
+        info!("Returning entry from cache.");
         Ok(self.entry_cache.get(&(url.to_string(), user.to_string())).context("Entry does not exist in cache")?)
     }
 
+    #[tracing::instrument]
     fn pad_string(&self, input: &str) -> String {
         let mut output = input.to_string();
 
@@ -128,19 +153,25 @@ impl CredentialManager {
         output
     }
 
+    #[tracing::instrument]
     pub fn get_credential(&mut self, url: &str) -> Result<Option<Credential>> {
         if !self.has_credential(url)? {
+            debug!(url=url, "Entry did not exist in sqlite database.");
             return Ok(None);
         }
 
+        info!("Getting entry from sqlite database.");
         let database_rows = self.get_database_credential_iter(url)?;
         let database_credential = database_rows.first().context("No elements returned from database.")?;
-        let entry = self.get_entry(url, &database_credential.user)?;
 
+        info!("Getting password from operating system credential store.");
+        let entry = self.get_entry(url, &database_credential.user)?;
         let password = entry.get_password()?;
 
         let mut totp_command: Option<String> = None;
         if database_credential.totp_comand_encrypted.is_some() {
+            info!("Database has TOTP command, decrypting.");
+
             let padded_password = self.pad_string(password.as_str());
             let key: &Key<Aes256Gcm> = padded_password.as_bytes().into();
 
@@ -152,26 +183,34 @@ impl CredentialManager {
                 &nonce, 
                 database_credential.totp_comand_encrypted.clone().context("TOTP command is empty.")?.as_ref())?;
             totp_command = Some(String::from_utf8(plaintext)?);
+
+            info!("Decryption completed.")
         }
 
         Ok(Some(Credential::new(database_credential.user.clone(), password, totp_command)))
     }
 
+    #[tracing::instrument]
     pub fn has_credential(&self, url: &str) -> Result<bool> {
         let database_rows = self.get_database_credential_iter(url)?;
 
         Ok(!database_rows.is_empty())
     }
 
+    #[tracing::instrument]
     pub fn remove_credential(&mut self, url: &str) -> Result<()> {
         if self.has_credential(url)? {
+            debug!(url=url, "Entry found in sqlite database.");
+
             let database_rows = self.get_database_credential_iter(url)?;
             let database_credential = database_rows.first().context("No elements returned from database.")?;
 
+            info!("Removing entry from operating system credential store.");
             let entry = self.get_entry(url, &database_credential.user)?;
             entry.delete_credential()?;
             self.entry_cache.remove(&(url.to_string(), database_credential.user.to_string()));
 
+            info!("Removing entry from sqlite database.");
             let database = self.get_database()?;
 
             database.execute(
@@ -183,14 +222,17 @@ impl CredentialManager {
         Ok(())
     }
 
+    #[tracing::instrument]
     pub fn set_credential(&mut self, url: &str, credential: &Credential) -> Result<()> {
         if self.has_credential(url)? {
+            debug!("Credential exists already.  Removing it before continuing.");
             self.remove_credential(url)?;
         }
 
         let mut totp_comand_encrypted: Option<Vec<u8>> = None;
         let mut totp_nonce: Option<Vec<u8>> = None;
         if credential.totp_command.is_some() {
+            info!("Encrypting the totp command.");
             let padded_password = self.pad_string(credential.password.as_str());
             let key: &Key<Aes256Gcm> = padded_password.as_bytes().into();
 
@@ -200,8 +242,11 @@ impl CredentialManager {
 
             totp_comand_encrypted = Some(ciphertext);
             totp_nonce = Some(nonce.as_slice().to_vec());
+
+            info!("Finished encrypting the totp command.");
         }
 
+        info!("Storing credential into database.");
         let database = self.get_database()?;
         database.execute(
             "INSERT INTO Credentials (url, user, totp_command_encrypted, totp_nonce) VALUES (?1, ?2, ?3, ?4)",
@@ -212,6 +257,7 @@ impl CredentialManager {
                 totp_nonce,
         ))?;
 
+        info!("Storing the database into the operating system credential store.");
         let entry = self.get_entry(url, &credential.user)?;
         entry.set_password(&credential.password)?;
 

src/main.rs

@@ -6,7 +6,23 @@ mod credential_manager;
 mod synology_file_station;
 
 use subcommands::{LoginSubcommand, LogoutSubcommand, Subcommand};
+use tracing_appender::rolling;
+use tracing_subscriber::fmt::writer::MakeWriterExt;
 
+fn setup_logging() {
+    let log_file = rolling::daily("./logs", "log").with_max_level(tracing::Level::INFO);
+
+    tracing_subscriber::fmt()
+        .compact()
+        .with_file(true)
+        .with_line_number(true)
+        .with_thread_ids(true)
+        .with_target(false)
+        .with_writer(log_file)
+        .init();
+}
+
+#[tracing::instrument]
 fn cli() -> Command {
     Command::new("git-lfs-synology")
         .about("This is an implementation of a git lfs custom transfer agent. See https://github.com/git-lfs/git-lfs/blob/main/docs/custom-transfers.md for more information.")
@@ -53,6 +69,8 @@ fn cli() -> Command {
 }
 
 fn main() -> Result<()> {
+    setup_logging();
+
     let matches = cli().get_matches();
 
     match matches.subcommand() {

src/subcommands/login_subcommand.rs

@@ -5,10 +5,12 @@ use crate::subcommands::Subcommand;
 use crate::credential_manager::{Credential, CredentialManager};
 use crate::synology_file_station::SynologyFileStation;
 
+#[derive(Debug)]
 pub struct LoginSubcommand {
 }
 
 impl Subcommand for LoginSubcommand {
+    #[tracing::instrument]
     fn execute(&self, arg_matches: &ArgMatches) -> Result<()> {
         let url = arg_matches.get_one::<String>("URL").context("URL not provided.")?;
         let user = arg_matches.get_one::<String>("USER").context("USER not provided.")?;

src/subcommands/logout_subcommand.rs

@@ -4,10 +4,12 @@ use crate::credential_manager::CredentialManager;
 use anyhow::{Context, Result};
 use clap::ArgMatches;
 
+#[derive(Debug)]
 pub struct LogoutSubcommand {
 }
 
 impl Subcommand for LogoutSubcommand {
+    #[tracing::instrument]
     fn execute(&self, arg_matches: &ArgMatches) -> Result<()> {
         let url = arg_matches.get_one::<String>("URL").context("URL not provided.")?;
 

src/synology_file_station.rs

@@ -71,6 +71,7 @@ pub enum SynologyError {
     NoSuchTaskOfTheFileOperation = 599
 }
 
+#[derive(Debug)]
 pub struct SynologyFileStation {
     url: String
 }
@@ -82,6 +83,7 @@ impl SynologyFileStation {
         }
     }
 
+    #[tracing::instrument]
     pub fn login(&self, credential: &Credential) -> Result<(), SynologyError> {
         let totp = credential.totp();