diff --git a/src/activity_manager.rs b/src/activity_manager.rs index 7e8f797..98585c1 100644 --- a/src/activity_manager.rs +++ b/src/activity_manager.rs @@ -69,7 +69,10 @@ impl ActivityManager { let (config_client, error): (Option, Option) = 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 { + 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 { + 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 diff --git a/src/bookmarks/serializer.rs b/src/bookmarks/serializer.rs index 6a5b0be..6d7d597 100644 --- a/src/bookmarks/serializer.rs +++ b/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(), diff --git a/src/config/serializer.rs b/src/config/serializer.rs index dd5670d..2375243 100644 --- a/src/config/serializer.rs +++ b/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(), diff --git a/src/filetransfer/ftp_transfer.rs b/src/filetransfer/ftp_transfer.rs index 1d7d6e7..4b69880 100644 --- a/src/filetransfer/ftp_transfer.rs +++ b/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, ) -> Result, 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 { + 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 { 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, 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 = 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, 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, 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) -> 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) -> Result<(), FileTransferError> { + info!("Finalizing get"); match &mut self.stream { Some(stream) => match stream.finalize_get(readable) { Ok(_) => Ok(()), diff --git a/src/filetransfer/scp_transfer.rs b/src/filetransfer/scp_transfer.rs index 8a7011f..df17b47 100644 --- a/src/filetransfer/scp_transfer.rs +++ b/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 { 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, ) -> Result, FileTransferError> { // Setup tcp stream + info!("Connecting to {}:{}", address, port); let socket_addresses: Vec = match format!("{}:{}", address, port).to_socket_addrs() { Ok(s) => s.collect(), @@ -325,8 +344,10 @@ impl FileTransfer for ScpFileTransfer { let mut tcp: Option = 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 = 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 { + 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, 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))), diff --git a/src/filetransfer/sftp_transfer.rs b/src/filetransfer/sftp_transfer.rs index 7e2b62f..d63f1c4 100644 --- a/src/filetransfer/sftp_transfer.rs +++ b/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, ) -> Result, FileTransferError> { // Setup tcp stream + info!("Connecting to {}:{}", address, port); let socket_addresses: Vec = match format!("{}:{}", address, port).to_socket_addrs() { Ok(s) => s.collect(), @@ -267,6 +284,7 @@ impl FileTransfer for SftpFileTransfer { let mut tcp: Option = 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 { + 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 = 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 { + 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))), diff --git a/src/main.rs b/src/main.rs index e24f4fe..8a18190 100644 --- a/src/main.rs +++ b/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 = None; let mut protocol: FileTransferProtocol = FileTransferProtocol::Sftp; // Default protocol let mut ticks: Duration = Duration::from_millis(10); + let mut log_level: Option = Some(logging::LevelFilter::Info); //Process options let mut opts = Options::new(); opts.optopt("P", "password", "Provide password from CLI", ""); opts.optopt("T", "ticks", "Set UI ticks; default 10ms", ""); + 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); } diff --git a/src/system/logging.rs b/src/system/logging.rs index 35d4603..c429749 100644 --- a/src/system/logging.rs +++ b/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()); } }