Working on logging

src/activity_manager.rs

@@ -69,7 +69,10 @@ impl ActivityManager {
         let (config_client, error): (Option<ConfigClient>, Option<String>) =
             match Self::init_config_client() {
                 Ok(cli) => (Some(cli), None),
-                Err(err) => (None, Some(err)),
+                Err(err) => {
+                    error!("Failed to initialize config client: {}", err);
+                    (None, Some(err))
+                }
             };
         let ctx: Context = Context::new(config_client, error);
         Ok(ActivityManager {
@@ -131,6 +134,7 @@ impl ActivityManager {
     /// Returns when activity terminates.
     /// Returns the next activity to run
     fn run_authentication(&mut self) -> Option<NextActivity> {
+        info!("Starting AuthActivity...");
         // Prepare activity
         let mut activity: AuthActivity = AuthActivity::default();
         // Prepare result
@@ -138,7 +142,10 @@ impl ActivityManager {
         // Get context
         let ctx: Context = match self.context.take() {
             Some(ctx) => ctx,
-            None => return None,
+            None => {
+                error!("Failed to start AuthActivity: context is None");
+                return None;
+            }
         };
         // Create activity
         activity.on_create(ctx);
@@ -149,16 +156,19 @@ impl ActivityManager {
             if let Some(exit_reason) = activity.will_umount() {
                 match exit_reason {
                     ExitReason::Quit => {
+                        info!("AuthActivity terminated due to 'Quit'");
                         result = None;
                         break;
                     }
                     ExitReason::EnterSetup => {
                         // User requested activity
+                        info!("AuthActivity terminated due to 'EnterSetup'");
                         result = Some(NextActivity::SetupActivity);
                         break;
                     }
                     ExitReason::Connect => {
                         // User submitted, set next activity
+                        info!("AuthActivity terminated due to 'Connect'");
                         result = Some(NextActivity::FileTransfer);
                         break;
                     }
@@ -170,6 +180,7 @@ impl ActivityManager {
         }
         // Destroy activity
         self.context = activity.on_destroy();
+        info!("AuthActivity destroyed");
         result
     }
 
@@ -179,15 +190,22 @@ impl ActivityManager {
     /// Returns when activity terminates.
     /// Returns the next activity to run
     fn run_filetransfer(&mut self) -> Option<NextActivity> {
+        info!("Starting FileTransferActivity");
         // Get context
         let mut ctx: Context = match self.context.take() {
             Some(ctx) => ctx,
-            None => return None,
+            None => {
+                error!("Failed to start FileTransferActivity: context is None");
+                return None;
+            }
         };
         // If ft params is None, return None
         let ft_params: &FileTransferParams = match ctx.ft_params.as_ref() {
             Some(ft_params) => &ft_params,
-            None => return None,
+            None => {
+                error!("Failed to start FileTransferActivity: file transfer params is None");
+                return None;
+            }
         };
         // Prepare activity
         let protocol: FileTransferProtocol = ft_params.protocol;
@@ -195,6 +213,7 @@ impl ActivityManager {
             Ok(host) => host,
             Err(err) => {
                 // Set error in context
+                error!("Failed to initialize localhost: {}", err);
                 ctx.set_error(format!("Could not initialize localhost: {}", err));
                 return None;
             }
@@ -211,11 +230,13 @@ impl ActivityManager {
             if let Some(exit_reason) = activity.will_umount() {
                 match exit_reason {
                     ExitReason::Quit => {
+                        info!("FileTransferActivity terminated due to 'Quit'");
                         result = None;
                         break;
                     }
                     ExitReason::Disconnect => {
                         // User disconnected, set next activity to authentication
+                        info!("FileTransferActivity terminated due to 'Authentication'");
                         result = Some(NextActivity::Authentication);
                         break;
                     }
@@ -241,7 +262,10 @@ impl ActivityManager {
         // Get context
         let ctx: Context = match self.context.take() {
             Some(ctx) => ctx,
-            None => return None,
+            None => {
+                error!("Failed to start SetupActivity: context is None");
+                return None;
+            }
         };
         // Create activity
         activity.on_create(ctx);
@@ -250,6 +274,7 @@ impl ActivityManager {
             activity.on_draw();
             // Check if activity has terminated
             if let Some(ExitReason::Quit) = activity.will_umount() {
+                info!("SetupActivity terminated due to 'Quit'");
                 break;
             }
             // Sleep for ticks

src/bookmarks/serializer.rs

@@ -50,6 +50,7 @@ impl BookmarkSerializer {
                 ))
             }
         };
+        trace!("Serialized new bookmarks data: {}", data);
         // Write file
         match writable.write_all(data.as_bytes()) {
             Ok(_) => Ok(()),
@@ -72,9 +73,13 @@ impl BookmarkSerializer {
                 err.to_string(),
             ));
         }
+        trace!("Read bookmarks from file: {}", data);
         // Deserialize
         match toml::de::from_str(data.as_str()) {
-            Ok(hosts) => Ok(hosts),
+            Ok(bookmarks) => {
+                debug!("Read bookmarks from file {:?}", bookmarks);
+                Ok(bookmarks)
+            }
             Err(err) => Err(SerializerError::new_ex(
                 SerializerErrorKind::SyntaxError,
                 err.to_string(),

src/config/serializer.rs

@@ -50,6 +50,7 @@ impl ConfigSerializer {
                 ))
             }
         };
+        trace!("Serialized new configuration data: {}", data);
         // Write file
         match writable.write_all(data.as_bytes()) {
             Ok(_) => Ok(()),
@@ -72,9 +73,13 @@ impl ConfigSerializer {
                 err.to_string(),
             ));
         }
+        trace!("Read configuration from file: {}", data);
         // Deserialize
         match toml::de::from_str(data.as_str()) {
-            Ok(hosts) => Ok(hosts),
+            Ok(config) => {
+                debug!("Read config from file {:?}", config);
+                Ok(config)
+            }
             Err(err) => Err(SerializerError::new_ex(
                 SerializerErrorKind::SyntaxError,
                 err.to_string(),

src/filetransfer/ftp_transfer.rs

@@ -34,6 +34,7 @@ extern crate regex;
 
 use super::{FileTransfer, FileTransferError, FileTransferErrorType};
 use crate::fs::{FsDirectory, FsEntry, FsFile};
+use crate::utils::fmt::{fmt_time, shadow_password};
 use crate::utils::parser::{parse_datetime, parse_lstime};
 
 // Includes
@@ -105,6 +106,7 @@ impl FtpFileTransfer {
         lazy_static! {
             static ref LS_RE: Regex = Regex::new(r#"^([\-ld])([\-rwxs]{9})\s+(\d+)\s+(\w+)\s+(\w+)\s+(\d+)\s+(\w{3}\s+\d{1,2}\s+(?:\d{1,2}:\d{1,2}|\d{4}))\s+(.+)$"#).unwrap();
         }
+        debug!("Parsing LIST (UNIX) line: '{}'", line);
         // Apply regex to result
         match LS_RE.captures(line) {
             // String matches regex
@@ -182,6 +184,7 @@ impl FtpFileTransfer {
                 };
                 // Check if file_name is '.' or '..'
                 if file_name.as_str() == "." || file_name.as_str() == ".." {
+                    debug!("File name is {}; ignoring entry", file_name);
                     return Err(());
                 }
                 // Get symlink
@@ -236,6 +239,19 @@ impl FtpFileTransfer {
                     .extension()
                     .map(|s| String::from(s.to_string_lossy()));
                 // Return
+                debug!("Follows LIST line '{}' attributes", line);
+                debug!("Is directory? {}", is_dir);
+                debug!("Is symlink? {}", is_symlink);
+                debug!("name: {}", file_name);
+                debug!("abs_path: {}", abs_path.display());
+                debug!("last_change_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("last_access_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("creation_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("symlink: {:?}", symlink);
+                debug!("user: {:?}", uid);
+                debug!("group: {:?}", gid);
+                debug!("unix_pex: {:?}", unix_pex);
+                debug!("---------------------------------------");
                 // Push to entries
                 Ok(match is_dir {
                     true => FsEntry::Directory(FsDirectory {
@@ -287,6 +303,7 @@ impl FtpFileTransfer {
             )
             .unwrap();
         }
+        debug!("Parsing LIST (DOS) line: '{}'", line);
         // Apply regex to result
         match DOS_RE.captures(line) {
             // String matches regex
@@ -324,6 +341,14 @@ impl FtpFileTransfer {
                     .as_path()
                     .extension()
                     .map(|s| String::from(s.to_string_lossy()));
+                debug!("Follows LIST line '{}' attributes", line);
+                debug!("Is directory? {}", is_dir);
+                debug!("name: {}", file_name);
+                debug!("abs_path: {}", abs_path.display());
+                debug!("last_change_time: {}", fmt_time(time, "%Y-%m-%dT%H:%M:%S"));
+                debug!("last_access_time: {}", fmt_time(time, "%Y-%m-%dT%H:%M:%S"));
+                debug!("creation_time: {}", fmt_time(time, "%Y-%m-%dT%H:%M:%S"));
+                debug!("---------------------------------------");
                 // Return entry
                 Ok(match is_dir {
                     true => FsEntry::Directory(FsDirectory {
@@ -382,17 +407,20 @@ impl FileTransfer for FtpFileTransfer {
         password: Option<String>,
     ) -> Result<Option<String>, FileTransferError> {
         // Get stream
+        info!("Connecting to {}:{}", address, port);
         let mut stream: FtpStream = match FtpStream::connect(format!("{}:{}", address, port)) {
             Ok(stream) => stream,
             Err(err) => {
+                error!("Failed to connect: {}", err);
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ConnectionError,
                     err.to_string(),
-                ))
+                ));
             }
         };
         // If SSL, open secure session
         if self.ftps {
+            info!("Setting up TLS stream...");
             let ctx = match TlsConnector::builder()
                 .danger_accept_invalid_certs(true)
                 .danger_accept_invalid_hostnames(true)
@@ -400,19 +428,21 @@ impl FileTransfer for FtpFileTransfer {
             {
                 Ok(tls) => tls,
                 Err(err) => {
+                    error!("Failed to setup TLS stream: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::SslError,
                         err.to_string(),
-                    ))
+                    ));
                 }
             };
             stream = match stream.into_secure(ctx, address.as_str()) {
                 Ok(s) => s,
                 Err(err) => {
+                    error!("Failed to setup TLS stream: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::SslError,
                         err.to_string(),
-                    ))
+                    ));
                 }
             };
         }
@@ -425,14 +455,22 @@ impl FileTransfer for FtpFileTransfer {
             Some(pwd) => pwd,
             None => String::new(),
         };
+        info!(
+            "Signin in with username: {}, password: {}",
+            username,
+            shadow_password(password.as_str())
+        );
         if let Err(err) = stream.login(username.as_str(), password.as_str()) {
+            error!("Login failed: {}", err);
             return Err(FileTransferError::new_ex(
                 FileTransferErrorType::AuthenticationFailed,
                 err.to_string(),
             ));
         }
+        debug!("Setting transfer type to Binary");
         // Initialize file type
         if let Err(err) = stream.transfer_type(FileType::Binary) {
+            error!("Failed to set transfer type to binary: {}", err);
             return Err(FileTransferError::new_ex(
                 FileTransferErrorType::ProtocolError,
                 err.to_string(),
@@ -440,6 +478,7 @@ impl FileTransfer for FtpFileTransfer {
         }
         // Set stream
         self.stream = Some(stream);
+        info!("Connection successfully established");
         // Return OK
         Ok(self.stream.as_ref().unwrap().get_welcome_msg())
     }
@@ -449,6 +488,7 @@ impl FileTransfer for FtpFileTransfer {
     /// Disconnect from the remote server
 
     fn disconnect(&mut self) -> Result<(), FileTransferError> {
+        info!("Disconnecting from FTP server...");
         match &mut self.stream {
             Some(stream) => match stream.quit() {
                 Ok(_) => Ok(()),
@@ -475,6 +515,7 @@ impl FileTransfer for FtpFileTransfer {
     /// Print working directory
 
     fn pwd(&mut self) -> Result<PathBuf, FileTransferError> {
+        info!("PWD");
         match &mut self.stream {
             Some(stream) => match stream.pwd() {
                 Ok(path) => Ok(PathBuf::from(path.as_str())),
@@ -495,6 +536,7 @@ impl FileTransfer for FtpFileTransfer {
 
     fn change_dir(&mut self, dir: &Path) -> Result<PathBuf, FileTransferError> {
         let dir: PathBuf = Self::resolve(dir);
+        info!("Changing directory to {}", dir.display());
         match &mut self.stream {
             Some(stream) => match stream.cwd(&dir.as_path().to_string_lossy()) {
                 Ok(_) => Ok(dir),
@@ -514,6 +556,7 @@ impl FileTransfer for FtpFileTransfer {
     /// Copy file to destination
     fn copy(&mut self, _src: &FsEntry, _dst: &Path) -> Result<(), FileTransferError> {
         // FTP doesn't support file copy
+        debug!("COPY issues (will fail, since unsupported)");
         Err(FileTransferError::new(
             FileTransferErrorType::UnsupportedFeature,
         ))
@@ -525,9 +568,11 @@ impl FileTransfer for FtpFileTransfer {
 
     fn list_dir(&mut self, path: &Path) -> Result<Vec<FsEntry>, FileTransferError> {
         let dir: PathBuf = Self::resolve(path);
+        info!("LIST dir {}", dir.display());
         match &mut self.stream {
             Some(stream) => match stream.list(Some(&dir.as_path().to_string_lossy())) {
                 Ok(entries) => {
+                    debug!("Got {} lines in LIST result", entries.len());
                     // Prepare result
                     let mut result: Vec<FsEntry> = Vec::with_capacity(entries.len());
                     // Iterate over entries
@@ -536,6 +581,11 @@ impl FileTransfer for FtpFileTransfer {
                             result.push(file);
                         }
                     }
+                    debug!(
+                        "{} out of {} were valid entries",
+                        result.len(),
+                        entries.len()
+                    );
                     Ok(result)
                 }
                 Err(err) => Err(FileTransferError::new_ex(
@@ -554,6 +604,7 @@ impl FileTransfer for FtpFileTransfer {
     /// Make directory
     fn mkdir(&mut self, dir: &Path) -> Result<(), FileTransferError> {
         let dir: PathBuf = Self::resolve(dir);
+        info!("MKDIR {}", dir.display());
         match &mut self.stream {
             Some(stream) => match stream.mkdir(&dir.as_path().to_string_lossy()) {
                 Ok(_) => Ok(()),
@@ -577,9 +628,11 @@ impl FileTransfer for FtpFileTransfer {
                 FileTransferErrorType::UninitializedSession,
             ));
         }
+        info!("Removing entry {}", fsentry.get_abs_path().display());
         match fsentry {
             // Match fs entry...
             FsEntry::File(file) => {
+                debug!("entry is a file; removing file");
                 // Remove file directly
                 match self.stream.as_mut().unwrap().rm(file.name.as_ref()) {
                     Ok(_) => Ok(()),
@@ -591,9 +644,11 @@ impl FileTransfer for FtpFileTransfer {
             }
             FsEntry::Directory(dir) => {
                 // Get directory files
+                debug!("Entry is a directory; iterating directory entries");
                 match self.list_dir(dir.abs_path.as_path()) {
                     Ok(files) => {
                         // Remove recursively files
+                        debug!("Removing {} entries from directory...", files.len());
                         for file in files.iter() {
                             if let Err(err) = self.remove(&file) {
                                 return Err(FileTransferError::new_ex(
@@ -603,6 +658,7 @@ impl FileTransfer for FtpFileTransfer {
                             }
                         }
                         // Once all files in directory have been deleted, remove directory
+                        debug!("Finally removing directory {}", dir.name);
                         match self.stream.as_mut().unwrap().rmdir(dir.name.as_str()) {
                             Ok(_) => Ok(()),
                             Err(err) => Err(FileTransferError::new_ex(
@@ -625,6 +681,11 @@ impl FileTransfer for FtpFileTransfer {
     /// Rename file or a directory
     fn rename(&mut self, file: &FsEntry, dst: &Path) -> Result<(), FileTransferError> {
         let dst: PathBuf = Self::resolve(dst);
+        info!(
+            "Renaming {} to {}",
+            file.get_abs_path().display(),
+            dst.display()
+        );
         match &mut self.stream {
             Some(stream) => {
                 // Get name
@@ -691,6 +752,7 @@ impl FileTransfer for FtpFileTransfer {
         file_name: &Path,
     ) -> Result<Box<dyn Write>, FileTransferError> {
         let file_name: PathBuf = Self::resolve(file_name);
+        info!("Sending file {}", file_name.display());
         match &mut self.stream {
             Some(stream) => match stream.put_with_stream(&file_name.as_path().to_string_lossy()) {
                 Ok(writer) => Ok(Box::new(writer)), // NOTE: don't use BufWriter here, since already returned by the library
@@ -710,6 +772,7 @@ impl FileTransfer for FtpFileTransfer {
     /// Receive file from remote with provided name
     /// Returns file and its size
     fn recv_file(&mut self, file: &FsFile) -> Result<Box<dyn Read>, FileTransferError> {
+        info!("Receiving file {}", file.abs_path.display());
         match &mut self.stream {
             Some(stream) => match stream.get(&file.abs_path.as_path().to_string_lossy()) {
                 Ok(reader) => Ok(Box::new(reader)), // NOTE: don't use BufReader here, since already returned by the library
@@ -732,6 +795,7 @@ impl FileTransfer for FtpFileTransfer {
     /// This is necessary for some protocols such as FTP.
     /// You must call this method each time you want to finalize the write of the remote file.
     fn on_sent(&mut self, writable: Box<dyn Write>) -> Result<(), FileTransferError> {
+        info!("Finalizing put stream");
         match &mut self.stream {
             Some(stream) => match stream.finalize_put_stream(writable) {
                 Ok(_) => Ok(()),
@@ -754,6 +818,7 @@ impl FileTransfer for FtpFileTransfer {
     /// This mighe be necessary for some protocols.
     /// You must call this method each time you want to finalize the read of the remote file.
     fn on_recv(&mut self, readable: Box<dyn Read>) -> Result<(), FileTransferError> {
+        info!("Finalizing get");
         match &mut self.stream {
             Some(stream) => match stream.finalize_get(readable) {
                 Ok(_) => Ok(()),

src/filetransfer/scp_transfer.rs

@@ -35,6 +35,7 @@ extern crate ssh2;
 use super::{FileTransfer, FileTransferError, FileTransferErrorType};
 use crate::fs::{FsDirectory, FsEntry, FsFile};
 use crate::system::sshkey_storage::SshKeyStorage;
+use crate::utils::fmt::{fmt_time, shadow_password};
 use crate::utils::parser::parse_lstime;
 
 // Includes
@@ -90,6 +91,7 @@ impl ScpFileTransfer {
         lazy_static! {
             static ref LS_RE: Regex = Regex::new(r#"^([\-ld])([\-rwxs]{9})\s+(\d+)\s+(\w+)\s+(\w+)\s+(\d+)\s+(\w{3}\s+\d{1,2}\s+(?:\d{1,2}:\d{1,2}|\d{4}))\s+(.+)$"#).unwrap();
         }
+        debug!("Parsing LS line: '{}'", line);
         // Apply regex to result
         match LS_RE.captures(line) {
             // String matches regex
@@ -167,6 +169,7 @@ impl ScpFileTransfer {
                 };
                 // Check if file_name is '.' or '..'
                 if file_name.as_str() == "." || file_name.as_str() == ".." {
+                    debug!("File name is {}; ignoring entry", file_name);
                     return Err(());
                 }
                 // Get symlink; PATH mustn't be equal to filename
@@ -200,6 +203,19 @@ impl ScpFileTransfer {
                     .extension()
                     .map(|s| String::from(s.to_string_lossy()));
                 // Return
+                debug!("Follows LS line '{}' attributes", line);
+                debug!("Is directory? {}", is_dir);
+                debug!("Is symlink? {}", is_symlink);
+                debug!("name: {}", file_name);
+                debug!("abs_path: {}", abs_path.display());
+                debug!("last_change_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("last_access_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("creation_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+                debug!("symlink: {:?}", symlink);
+                debug!("user: {:?}", uid);
+                debug!("group: {:?}", gid);
+                debug!("unix_pex: {:?}", unix_pex);
+                debug!("---------------------------------------");
                 // Push to entries
                 Ok(match is_dir {
                     true => FsEntry::Directory(FsDirectory {
@@ -262,6 +278,7 @@ impl ScpFileTransfer {
     fn perform_shell_cmd(&mut self, cmd: &str) -> Result<String, FileTransferError> {
         match self.session.as_mut() {
             Some(session) => {
+                debug!("Running command: {}", cmd);
                 // Create channel
                 let mut channel: Channel = match session.channel_session() {
                     Ok(ch) => ch,
@@ -285,6 +302,7 @@ impl ScpFileTransfer {
                     Ok(_) => {
                         // Wait close
                         let _ = channel.wait_close();
+                        debug!("Command output: {}", output);
                         Ok(output)
                     }
                     Err(err) => Err(FileTransferError::new_ex(
@@ -312,6 +330,7 @@ impl FileTransfer for ScpFileTransfer {
         password: Option<String>,
     ) -> Result<Option<String>, FileTransferError> {
         // Setup tcp stream
+        info!("Connecting to {}:{}", address, port);
         let socket_addresses: Vec<SocketAddr> =
             match format!("{}:{}", address, port).to_socket_addrs() {
                 Ok(s) => s.collect(),
@@ -325,8 +344,10 @@ impl FileTransfer for ScpFileTransfer {
         let mut tcp: Option<TcpStream> = None;
         // Try addresses
         for socket_addr in socket_addresses.iter() {
+            debug!("Trying socket address {}", socket_addr);
             match TcpStream::connect_timeout(&socket_addr, Duration::from_secs(30)) {
                 Ok(stream) => {
+                    debug!("{} succeded", socket_addr);
                     tcp = Some(stream);
                     break;
                 }
@@ -337,26 +358,30 @@ impl FileTransfer for ScpFileTransfer {
         let tcp: TcpStream = match tcp {
             Some(t) => t,
             None => {
+                error!("No suitable socket address found; connection timeout");
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ConnectionError,
                     String::from("Connection timeout"),
-                ))
+                ));
             }
         };
         // Create session
         let mut session: Session = match Session::new() {
             Ok(s) => s,
             Err(err) => {
+                error!("Could not create session: {}", err);
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ConnectionError,
                     err.to_string(),
-                ))
+                ));
             }
         };
         // Set TCP stream
         session.set_tcp_stream(tcp);
         // Open connection
+        debug!("Initializing handshake");
         if let Err(err) = session.handshake() {
+            error!("Handshake failed: {}", err);
             return Err(FileTransferError::new_ex(
                 FileTransferErrorType::ConnectionError,
                 err.to_string(),
@@ -372,6 +397,11 @@ impl FileTransfer for ScpFileTransfer {
             .resolve(address.as_str(), username.as_str())
         {
             Some(rsa_key) => {
+                debug!(
+                    "Authenticating with user {} and RSA key {}",
+                    username,
+                    rsa_key.display()
+                );
                 // Authenticate with RSA key
                 if let Err(err) = session.userauth_pubkey_file(
                     username.as_str(),
@@ -379,6 +409,7 @@ impl FileTransfer for ScpFileTransfer {
                     rsa_key.as_path(),
                     password.as_deref(),
                 ) {
+                    error!("Authentication failed: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::AuthenticationFailed,
                         err.to_string(),
@@ -387,10 +418,16 @@ impl FileTransfer for ScpFileTransfer {
             }
             None => {
                 // Proceeed with username/password authentication
+                debug!(
+                    "Authenticating with username {} and password {}",
+                    username,
+                    shadow_password(password.as_deref().unwrap_or(""))
+                );
                 if let Err(err) = session.userauth_password(
                     username.as_str(),
                     password.unwrap_or_else(|| String::from("")).as_str(),
                 ) {
+                    error!("Authentication failed: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::AuthenticationFailed,
                         err.to_string(),
@@ -400,13 +437,22 @@ impl FileTransfer for ScpFileTransfer {
         }
         // Get banner
         let banner: Option<String> = session.banner().map(String::from);
+        debug!(
+            "Connection established: {}",
+            banner.as_deref().unwrap_or("")
+        );
         // Set session
         self.session = Some(session);
         // Get working directory
+        debug!("Getting working directory...");
         match self.perform_shell_cmd("pwd") {
             Ok(output) => self.wrkdir = PathBuf::from(output.as_str().trim()),
             Err(err) => return Err(err),
         }
+        info!(
+            "Connection established; working directory: {}",
+            self.wrkdir.display()
+        );
         Ok(banner)
     }
 
@@ -414,6 +460,7 @@ impl FileTransfer for ScpFileTransfer {
     ///
     /// Disconnect from the remote server
     fn disconnect(&mut self) -> Result<(), FileTransferError> {
+        info!("Disconnecting from remote...");
         match self.session.as_ref() {
             Some(session) => {
                 // Disconnect (greet server with 'Mandi' as they do in Friuli)
@@ -447,6 +494,7 @@ impl FileTransfer for ScpFileTransfer {
     /// Print working directory
 
     fn pwd(&mut self) -> Result<PathBuf, FileTransferError> {
+        info!("PWD: {}", self.wrkdir.display());
         match self.is_connected() {
             true => Ok(self.wrkdir.clone()),
             false => Err(FileTransferError::new(
@@ -471,6 +519,7 @@ impl FileTransfer for ScpFileTransfer {
                         Self::resolve(p.as_path())
                     }
                 };
+                info!("Changing working directory to {}", remote_path.display());
                 // Change directory
                 match self.perform_shell_cmd_with_path(
                     p.as_path(),
@@ -484,6 +533,7 @@ impl FileTransfer for ScpFileTransfer {
                             true => {
                                 // Set working directory
                                 self.wrkdir = PathBuf::from(&output.as_str()[1..].trim());
+                                info!("Changed working directory to {}", self.wrkdir.display());
                                 Ok(self.wrkdir.clone())
                             }
                             false => Err(FileTransferError::new_ex(
@@ -512,6 +562,11 @@ impl FileTransfer for ScpFileTransfer {
         match self.is_connected() {
             true => {
                 let dst: PathBuf = Self::resolve(dst);
+                info!(
+                    "Copying {} to {}",
+                    src.get_abs_path().display(),
+                    dst.display()
+                );
                 // Run `cp -rf`
                 let p: PathBuf = self.wrkdir.clone();
                 match self.perform_shell_cmd_with_path(
@@ -555,6 +610,7 @@ impl FileTransfer for ScpFileTransfer {
         match self.is_connected() {
             true => {
                 // Send ls -l to path
+                info!("Getting file entries in {}", path.display());
                 let path: PathBuf = Self::resolve(path);
                 let p: PathBuf = self.wrkdir.clone();
                 match self.perform_shell_cmd_with_path(
@@ -572,6 +628,11 @@ impl FileTransfer for ScpFileTransfer {
                                 entries.push(entry);
                             }
                         }
+                        info!(
+                            "Found {} out of {} valid file entries",
+                            entries.len(),
+                            lines.len()
+                        );
                         Ok(entries)
                     }
                     Err(err) => Err(FileTransferError::new_ex(
@@ -594,6 +655,7 @@ impl FileTransfer for ScpFileTransfer {
         match self.is_connected() {
             true => {
                 let dir: PathBuf = Self::resolve(dir);
+                info!("Making directory {}", dir.display());
                 let p: PathBuf = self.wrkdir.clone();
                 // Mkdir dir && echo 0
                 match self.perform_shell_cmd_with_path(
@@ -632,6 +694,7 @@ impl FileTransfer for ScpFileTransfer {
             true => {
                 // Get path
                 let path: PathBuf = file.get_abs_path();
+                info!("Removing file {}", path.display());
                 let p: PathBuf = self.wrkdir.clone();
                 match self.perform_shell_cmd_with_path(
                     p.as_path(),
@@ -669,6 +732,7 @@ impl FileTransfer for ScpFileTransfer {
                 // Get path
                 let dst: PathBuf = Self::resolve(dst);
                 let path: PathBuf = file.get_abs_path();
+                info!("Renaming {} to {}", path.display(), dst.display());
                 let p: PathBuf = self.wrkdir.clone();
                 match self.perform_shell_cmd_with_path(
                     p.as_path(),
@@ -717,6 +781,7 @@ impl FileTransfer for ScpFileTransfer {
         match self.is_connected() {
             true => {
                 let p: PathBuf = self.wrkdir.clone();
+                info!("Stat {}", path.display());
                 // make command; Directories require `-d` option
                 let cmd: String = match path.to_string_lossy().ends_with('/') {
                     true => format!("ls -ld \"{}\"", path.display()),
@@ -760,6 +825,7 @@ impl FileTransfer for ScpFileTransfer {
         match self.is_connected() {
             true => {
                 let p: PathBuf = self.wrkdir.clone();
+                info!("Executing command {}", cmd);
                 match self.perform_shell_cmd_with_path(p.as_path(), cmd) {
                     Ok(output) => Ok(output),
                     Err(err) => Err(FileTransferError::new_ex(
@@ -788,7 +854,13 @@ impl FileTransfer for ScpFileTransfer {
         match self.session.as_ref() {
             Some(session) => {
                 let file_name: PathBuf = Self::resolve(file_name);
+                info!(
+                    "Sending file {} to {}",
+                    local.abs_path.display(),
+                    file_name.display()
+                );
                 // Set blocking to true
+                debug!("blocking channel...");
                 session.set_blocking(true);
                 // Calculate file mode
                 let mode: i32 = match local.unix_pex {
@@ -818,6 +890,10 @@ impl FileTransfer for ScpFileTransfer {
                     Ok(metadata) => metadata.len(),
                     Err(_) => local.size as u64, // NOTE: fallback to fsentry size
                 };
+                debug!(
+                    "File mode {:?}; mtime: {}, atime: {}; file size: {}",
+                    mode, times.0, times.1, file_size
+                );
                 // Send file
                 match session.scp_send(file_name.as_path(), mode, file_size, Some(times)) {
                     Ok(channel) => Ok(Box::new(BufWriter::with_capacity(65536, channel))),
@@ -840,7 +916,9 @@ impl FileTransfer for ScpFileTransfer {
     fn recv_file(&mut self, file: &FsFile) -> Result<Box<dyn Read>, FileTransferError> {
         match self.session.as_ref() {
             Some(session) => {
+                info!("Receiving file {}", file.abs_path.display());
                 // Set blocking to true
+                debug!("Set blocking...");
                 session.set_blocking(true);
                 match session.scp_recv(file.abs_path.as_path()) {
                     Ok(reader) => Ok(Box::new(BufReader::with_capacity(65536, reader.0))),

src/filetransfer/sftp_transfer.rs

@@ -32,6 +32,7 @@ extern crate ssh2;
 use super::{FileTransfer, FileTransferError, FileTransferErrorType};
 use crate::fs::{FsDirectory, FsEntry, FsFile};
 use crate::system::sshkey_storage::SshKeyStorage;
+use crate::utils::fmt::{fmt_time, shadow_password};
 
 // Includes
 use ssh2::{Channel, FileStat, OpenFlags, OpenType, Session, Sftp};
@@ -159,6 +160,19 @@ impl SftpFileTransfer {
             }
             false => None,
         };
+        debug!("Follows {} attributes", path.display());
+        debug!("Is directory? {}", metadata.is_dir());
+        debug!("Is symlink? {}", is_symlink);
+        debug!("name: {}", file_name);
+        debug!("abs_path: {}", path.display());
+        debug!("last_change_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+        debug!("last_access_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+        debug!("creation_time: {}", fmt_time(mtime, "%Y-%m-%dT%H:%M:%S"));
+        debug!("symlink: {:?}", symlink);
+        debug!("user: {:?}", uid);
+        debug!("group: {:?}", gid);
+        debug!("unix_pex: {:?}", pex);
+        debug!("---------------------------------------");
         // Is a directory?
         match metadata.is_dir() {
             true => FsEntry::Directory(FsDirectory {
@@ -205,6 +219,7 @@ impl SftpFileTransfer {
         match self.session.as_mut() {
             Some(session) => {
                 // Create channel
+                debug!("Running command: {}", cmd);
                 let mut channel: Channel = match session.channel_session() {
                     Ok(ch) => ch,
                     Err(err) => {
@@ -227,6 +242,7 @@ impl SftpFileTransfer {
                     Ok(_) => {
                         // Wait close
                         let _ = channel.wait_close();
+                        debug!("Command output: {}", output);
                         Ok(output)
                     }
                     Err(err) => Err(FileTransferError::new_ex(
@@ -254,6 +270,7 @@ impl FileTransfer for SftpFileTransfer {
         password: Option<String>,
     ) -> Result<Option<String>, FileTransferError> {
         // Setup tcp stream
+        info!("Connecting to {}:{}", address, port);
         let socket_addresses: Vec<SocketAddr> =
             match format!("{}:{}", address, port).to_socket_addrs() {
                 Ok(s) => s.collect(),
@@ -267,6 +284,7 @@ impl FileTransfer for SftpFileTransfer {
         let mut tcp: Option<TcpStream> = None;
         // Try addresses
         for socket_addr in socket_addresses.iter() {
+            debug!("Trying socket address {}", socket_addr);
             match TcpStream::connect_timeout(&socket_addr, Duration::from_secs(30)) {
                 Ok(stream) => {
                     tcp = Some(stream);
@@ -279,26 +297,30 @@ impl FileTransfer for SftpFileTransfer {
         let tcp: TcpStream = match tcp {
             Some(t) => t,
             None => {
+                error!("No suitable socket address found; connection timeout");
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ConnectionError,
                     String::from("Connection timeout"),
-                ))
+                ));
             }
         };
         // Create session
         let mut session: Session = match Session::new() {
             Ok(s) => s,
             Err(err) => {
+                error!("Could not create session: {}", err);
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ConnectionError,
                     err.to_string(),
-                ))
+                ));
             }
         };
         // Set TCP stream
         session.set_tcp_stream(tcp);
         // Open connection
+        debug!("Initializing handshake");
         if let Err(err) = session.handshake() {
+            error!("Handshake failed: {}", err);
             return Err(FileTransferError::new_ex(
                 FileTransferErrorType::ConnectionError,
                 err.to_string(),
@@ -314,6 +336,11 @@ impl FileTransfer for SftpFileTransfer {
             .resolve(address.as_str(), username.as_str())
         {
             Some(rsa_key) => {
+                debug!(
+                    "Authenticating with user {} and RSA key {}",
+                    username,
+                    rsa_key.display()
+                );
                 // Authenticate with RSA key
                 if let Err(err) = session.userauth_pubkey_file(
                     username.as_str(),
@@ -321,6 +348,7 @@ impl FileTransfer for SftpFileTransfer {
                     rsa_key.as_path(),
                     password.as_deref(),
                 ) {
+                    error!("Authentication failed: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::AuthenticationFailed,
                         err.to_string(),
@@ -329,10 +357,16 @@ impl FileTransfer for SftpFileTransfer {
             }
             None => {
                 // Proceeed with username/password authentication
+                debug!(
+                    "Authenticating with username {} and password {}",
+                    username,
+                    shadow_password(password.as_deref().unwrap_or(""))
+                );
                 if let Err(err) = session.userauth_password(
                     username.as_str(),
                     password.unwrap_or_else(|| String::from("")).as_str(),
                 ) {
+                    error!("Authentication failed: {}", err);
                     return Err(FileTransferError::new_ex(
                         FileTransferErrorType::AuthenticationFailed,
                         err.to_string(),
@@ -343,16 +377,19 @@ impl FileTransfer for SftpFileTransfer {
         // Set blocking to true
         session.set_blocking(true);
         // Get Sftp client
+        debug!("Getting SFTP client...");
         let sftp: Sftp = match session.sftp() {
             Ok(s) => s,
             Err(err) => {
+                error!("Could not get sftp client: {}", err);
                 return Err(FileTransferError::new_ex(
                     FileTransferErrorType::ProtocolError,
                     err.to_string(),
-                ))
+                ));
             }
         };
         // Get working directory
+        debug!("Getting working directory...");
         self.wrkdir = match sftp.realpath(PathBuf::from(".").as_path()) {
             Ok(p) => p,
             Err(err) => {
@@ -367,6 +404,11 @@ impl FileTransfer for SftpFileTransfer {
         self.session = Some(session);
         // Set sftp
         self.sftp = Some(sftp);
+        info!(
+            "Connection established: {}; working directory {}",
+            banner.as_deref().unwrap_or(""),
+            self.wrkdir.display()
+        );
         Ok(banner)
     }
 
@@ -374,6 +416,7 @@ impl FileTransfer for SftpFileTransfer {
     ///
     /// Disconnect from the remote server
     fn disconnect(&mut self) -> Result<(), FileTransferError> {
+        info!("Disconnecting from remote...");
         match self.session.as_ref() {
             Some(session) => {
                 // Disconnect (greet server with 'Mandi' as they do in Friuli)
@@ -407,6 +450,7 @@ impl FileTransfer for SftpFileTransfer {
     ///
     /// Print working directory
     fn pwd(&mut self) -> Result<PathBuf, FileTransferError> {
+        info!("PWD: {}", self.wrkdir.display());
         match self.sftp {
             Some(_) => Ok(self.wrkdir.clone()),
             None => Err(FileTransferError::new(
@@ -426,6 +470,7 @@ impl FileTransfer for SftpFileTransfer {
                     Ok(p) => p,
                     Err(err) => return Err(err),
                 };
+                info!("Changed working directory to {}", self.wrkdir.display());
                 Ok(self.wrkdir.clone())
             }
             None => Err(FileTransferError::new(
@@ -442,6 +487,11 @@ impl FileTransfer for SftpFileTransfer {
         match self.is_connected() {
             true => {
                 let dst: PathBuf = self.get_abs_path(dst);
+                info!(
+                    "Copying {} to {}",
+                    src.get_abs_path().display(),
+                    dst.display()
+                );
                 // Run `cp -rf`
                 match self.perform_shell_cmd_with_path(
                     format!(
@@ -486,6 +536,7 @@ impl FileTransfer for SftpFileTransfer {
                     Ok(p) => p,
                     Err(err) => return Err(err),
                 };
+                info!("Getting file entries in {}", path.display());
                 // Get files
                 match sftp.readdir(dir.as_path()) {
                     Err(err) => Err(FileTransferError::new_ex(
@@ -517,6 +568,7 @@ impl FileTransfer for SftpFileTransfer {
             Some(sftp) => {
                 // Make directory
                 let path: PathBuf = self.get_abs_path(PathBuf::from(dir).as_path());
+                info!("Making directory {}", path.display());
                 match sftp.mkdir(path.as_path(), 0o775) {
                     Ok(_) => Ok(()),
                     Err(err) => Err(FileTransferError::new_ex(
@@ -541,6 +593,7 @@ impl FileTransfer for SftpFileTransfer {
             ));
         }
         // Match if file is a file or a directory
+        info!("Removing file {}", file.get_abs_path().display());
         match file {
             FsEntry::File(f) => {
                 // Remove file
@@ -554,6 +607,7 @@ impl FileTransfer for SftpFileTransfer {
             }
             FsEntry::Directory(d) => {
                 // Remove recursively
+                debug!("{} is a directory; removing all directory entries", d.name);
                 // Get directory files
                 let directory_content: Vec<FsEntry> = match self.list_dir(d.abs_path.as_path()) {
                     Ok(entries) => entries,
@@ -585,6 +639,11 @@ impl FileTransfer for SftpFileTransfer {
                 FileTransferErrorType::UninitializedSession,
             )),
             Some(sftp) => {
+                info!(
+                    "Moving {} to {}",
+                    file.get_abs_path().display(),
+                    dst.display()
+                );
                 // Resolve destination path
                 let abs_dst: PathBuf = self.get_abs_path(dst);
                 // Get abs path of entry
@@ -611,6 +670,7 @@ impl FileTransfer for SftpFileTransfer {
                     Ok(p) => p,
                     Err(err) => return Err(err),
                 };
+                info!("Stat file {}", dir.display());
                 // Get file
                 match sftp.stat(dir.as_path()) {
                     Ok(metadata) => Ok(self.make_fsentry(dir.as_path(), &metadata)),
@@ -630,6 +690,7 @@ impl FileTransfer for SftpFileTransfer {
     ///
     /// Execute a command on remote host
     fn exec(&mut self, cmd: &str) -> Result<String, FileTransferError> {
+        info!("Executing command {}", cmd);
         match self.is_connected() {
             true => match self.perform_shell_cmd_with_path(cmd) {
                 Ok(output) => Ok(output),
@@ -660,14 +721,20 @@ impl FileTransfer for SftpFileTransfer {
             )),
             Some(sftp) => {
                 let remote_path: PathBuf = self.get_abs_path(file_name);
+                info!(
+                    "Sending file {} to {}",
+                    local.abs_path.display(),
+                    remote_path.display()
+                );
                 // Calculate file mode
                 let mode: i32 = match local.unix_pex {
                     None => 0o644,
                     Some((u, g, o)) => ((u as i32) << 6) + ((g as i32) << 3) + (o as i32),
                 };
+                debug!("File mode {:?}", mode);
                 match sftp.open_mode(
                     remote_path.as_path(),
-                    OpenFlags::WRITE | OpenFlags::CREATE | OpenFlags::APPEND | OpenFlags::TRUNCATE,
+                    OpenFlags::WRITE | OpenFlags::CREATE | OpenFlags::TRUNCATE,
                     mode,
                     OpenType::File,
                 ) {
@@ -695,6 +762,7 @@ impl FileTransfer for SftpFileTransfer {
                     Ok(p) => p,
                     Err(err) => return Err(err),
                 };
+                info!("Receiving file {}", remote_path.display());
                 // Open remote file
                 match sftp.open(remote_path.as_path()) {
                     Ok(file) => Ok(Box::new(BufReader::with_capacity(65536, file))),

src/main.rs

@@ -32,6 +32,8 @@ extern crate bitflags;
 #[macro_use]
 extern crate lazy_static;
 #[macro_use]
+extern crate log;
+#[macro_use]
 extern crate magic_crypt;
 extern crate rpassword;
 
@@ -55,6 +57,7 @@ mod utils;
 // namespaces
 use activity_manager::{ActivityManager, NextActivity};
 use filetransfer::FileTransferProtocol;
+use system::logging;
 
 /// ### print_usage
 ///
@@ -79,10 +82,13 @@ fn main() {
     let mut remote_wrkdir: Option<PathBuf> = None;
     let mut protocol: FileTransferProtocol = FileTransferProtocol::Sftp; // Default protocol
     let mut ticks: Duration = Duration::from_millis(10);
+    let mut log_level: Option<logging::LevelFilter> = Some(logging::LevelFilter::Info);
     //Process options
     let mut opts = Options::new();
     opts.optopt("P", "password", "Provide password from CLI", "<password>");
     opts.optopt("T", "ticks", "Set UI ticks; default 10ms", "<ms>");
+    opts.optflag("D", "debug", "Enable debug log level");
+    opts.optflag("q", "quiet", "Disable logging");
     opts.optflag("v", "version", "");
     opts.optflag("h", "help", "Print this menu");
     let matches = match opts.parse(&args[1..]) {
@@ -105,6 +111,13 @@ fn main() {
         );
         std::process::exit(255);
     }
+    // Logging
+    if matches.opt_present("q") {
+        log_level = None;
+    }
+    if matches.opt_present("D") {
+        log_level = Some(logging::LevelFilter::Trace);
+    }
     // Match password
     if let Some(passwd) = matches.opt_str("P") {
         password = Some(passwd);
@@ -155,9 +168,17 @@ fn main() {
         Ok(dir) => dir,
         Err(_) => PathBuf::from("/"),
     };
+    // Setup logging
+    if let Some(log_level) = log_level {
+        if let Err(err) = logging::init(log_level) {
+            eprintln!("Failed to initialize logging: {}", err);
+        }
+    }
+    info!("termscp {} started!", TERMSCP_VERSION);
     // Initialize client if necessary
     let mut start_activity: NextActivity = NextActivity::Authentication;
     if address.is_some() {
+        debug!("User has specified remote options: address: {:?}, port: {:?}, protocol: {:?}, user: {:?}, password: {}", address, port, protocol, username, utils::fmt::shadow_password(password.as_deref().unwrap_or("")));
         if password.is_none() {
             // Ask password if unspecified
             password = match rpassword::read_password_from_tty(Some("Password: ")) {
@@ -173,6 +194,10 @@ fn main() {
                     std::process::exit(255);
                 }
             };
+            debug!(
+                "Read password from tty: {}",
+                utils::fmt::shadow_password(password.as_deref().unwrap_or(""))
+            );
         }
         // In this case the first activity will be FileTransfer
         start_activity = NextActivity::FileTransfer;
@@ -190,7 +215,9 @@ fn main() {
         manager.set_filetransfer_params(address, port, protocol, username, password, remote_wrkdir);
     }
     // Run
+    info!("Starting activity manager...");
     manager.run(start_activity);
+    info!("termscp terminated");
     // Then return
     std::process::exit(0);
 }

src/system/logging.rs

@@ -29,14 +29,15 @@
 use crate::system::environment::{get_log_paths, init_config_dir};
 use crate::utils::file::open_file;
 // ext
-use simplelog::{Color, ConfigBuilder, Level, LevelFilter, WriteLogger};
+pub use simplelog::LevelFilter;
+use simplelog::{ConfigBuilder, WriteLogger};
 use std::fs::File;
 use std::path::PathBuf;
 
 /// ### init
 ///
 /// Initialize logger
-pub fn init() -> Result<(), String> {
+pub fn init(log_level: LevelFilter) -> Result<(), String> {
     // Init config dir
     let config_dir: PathBuf = match init_config_dir() {
         Ok(Some(p)) => p,
@@ -54,14 +55,9 @@ pub fn init() -> Result<(), String> {
     // Prepare log config
     let config = ConfigBuilder::new()
         .set_time_format_str("%Y-%m-%dT%H:%M:%S%z")
-        .set_level_color(Level::Trace, None)
-        .set_level_color(Level::Debug, Some(Color::Cyan))
-        .set_level_color(Level::Info, Some(Color::Yellow))
-        .set_level_color(Level::Warn, Some(Color::Magenta))
-        .set_level_color(Level::Error, Some(Color::Red))
         .build();
     // Make logger
-    WriteLogger::init(LevelFilter::Debug, config, file)
+    WriteLogger::init(log_level, config, file)
         .map_err(|e| format!("Failed to initialize logger: {}", e))
 }
 
@@ -72,6 +68,6 @@ mod test {
 
     #[test]
     fn test_system_logging_setup() {
-        assert!(init().is_ok());
+        assert!(init(LevelFilter::Trace).is_ok());
     }
 }