From e10fccf5cc19ad4281e5d6f383f98372ff6e8901 Mon Sep 17 00:00:00 2001 From: Hannes Laimer Date: Wed, 15 Jun 2022 08:19:49 +0000 Subject: [PATCH] pbs-client: replace print with log macro Signed-off-by: Hannes Laimer Signed-off-by: Wolfgang Bumiller --- pbs-client/Cargo.toml | 1 + pbs-client/src/backup_writer.rs | 103 +++++++++++---------------- pbs-client/src/catalog_shell.rs | 4 +- pbs-client/src/http_client.rs | 14 ++-- pbs-client/src/pxar/create.rs | 2 - pbs-client/src/pxar/extract.rs | 70 +++++------------- pbs-client/src/pxar/fuse.rs | 18 ++--- pbs-client/src/pxar/metadata.rs | 4 +- pbs-client/src/pxar_backup_stream.rs | 6 +- pbs-client/src/task_log.rs | 8 +-- pbs-client/src/tools/key_source.rs | 2 +- 11 files changed, 87 insertions(+), 145 deletions(-) diff --git a/pbs-client/Cargo.toml b/pbs-client/Cargo.toml index fbb516d4..50cbe9b1 100644 --- a/pbs-client/Cargo.toml +++ b/pbs-client/Cargo.toml @@ -17,6 +17,7 @@ hyper = { version = "0.14", features = [ "full" ] } lazy_static = "1.4" libc = "0.2" nix = "0.24" +log = "0.4" openssl = "0.10" percent-encoding = "2.1" pin-project-lite = "0.2" diff --git a/pbs-client/src/backup_writer.rs b/pbs-client/src/backup_writer.rs index a976bd43..6cf3543c 100644 --- a/pbs-client/src/backup_writer.rs +++ b/pbs-client/src/backup_writer.rs @@ -28,7 +28,6 @@ use super::{H2Client, HttpClient}; pub struct BackupWriter { h2: H2Client, abort: AbortHandle, - verbose: bool, crypt_config: Option>, } @@ -66,17 +65,11 @@ type UploadQueueSender = mpsc::Sender<(MergedChunkInfo, Option>; impl BackupWriter { - fn new( - h2: H2Client, - abort: AbortHandle, - crypt_config: Option>, - verbose: bool, - ) -> Arc { + fn new(h2: H2Client, abort: AbortHandle, crypt_config: Option>) -> Arc { Arc::new(Self { h2, abort, crypt_config, - verbose, }) } @@ -117,7 +110,7 @@ impl BackupWriter { .start_h2_connection(req, String::from(PROXMOX_BACKUP_PROTOCOL_ID_V1!())) .await?; - Ok(BackupWriter::new(h2, abort, crypt_config, debug)) + Ok(BackupWriter::new(h2, abort, crypt_config)) } pub async fn get(&self, path: &str, param: Option) -> Result { @@ -338,23 +331,23 @@ impl BackupWriter { None }, options.compress, - self.verbose, ) .await?; let size_dirty = upload_stats.size - upload_stats.size_reused; let size: HumanByte = upload_stats.size.into(); - let archive = if self.verbose { + let archive = if log::log_enabled!(log::Level::Debug) { archive_name } else { pbs_tools::format::strip_server_file_extension(archive_name) }; + if archive_name != CATALOG_NAME { let speed: HumanByte = ((size_dirty * 1_000_000) / (upload_stats.duration.as_micros() as usize)).into(); let size_dirty: HumanByte = size_dirty.into(); let size_compressed: HumanByte = upload_stats.size_compressed.into(); - println!( + log::info!( "{}: had to backup {} of {} (compressed {}) in {:.2}s", archive, size_dirty, @@ -362,30 +355,34 @@ impl BackupWriter { size_compressed, upload_stats.duration.as_secs_f64() ); - println!("{}: average backup speed: {}/s", archive, speed); + log::info!("{}: average backup speed: {}/s", archive, speed); } else { - println!("Uploaded backup catalog ({})", size); + log::info!("Uploaded backup catalog ({})", size); } if upload_stats.size_reused > 0 && upload_stats.size > 1024 * 1024 { let reused_percent = upload_stats.size_reused as f64 * 100. / upload_stats.size as f64; let reused: HumanByte = upload_stats.size_reused.into(); - println!( + log::info!( "{}: backup was done incrementally, reused {} ({:.1}%)", - archive, reused, reused_percent + archive, + reused, + reused_percent ); } - if self.verbose && upload_stats.chunk_count > 0 { - println!( + if log::log_enabled!(log::Level::Debug) && upload_stats.chunk_count > 0 { + log::debug!( "{}: Reused {} from {} chunks.", - archive, upload_stats.chunk_reused, upload_stats.chunk_count + archive, + upload_stats.chunk_reused, + upload_stats.chunk_count ); - println!( + log::debug!( "{}: Average chunk size was {}.", archive, HumanByte::from(upload_stats.size / upload_stats.chunk_count) ); - println!( + log::debug!( "{}: Average time per request: {} microseconds.", archive, (upload_stats.duration.as_micros()) / (upload_stats.chunk_count as u128) @@ -405,9 +402,7 @@ impl BackupWriter { }) } - fn response_queue( - verbose: bool, - ) -> ( + fn response_queue() -> ( mpsc::Sender, oneshot::Receiver>, ) { @@ -435,11 +430,7 @@ impl BackupWriter { response .map_err(Error::from) .and_then(H2Client::h2api_response) - .map_ok(move |result| { - if verbose { - println!("RESPONSE: {:?}", result) - } - }) + .map_ok(move |result| log::debug!("RESPONSE: {:?}", result)) .map_err(|err| format_err!("pipelined request failed: {}", err)) }) .map(|result| { @@ -454,7 +445,6 @@ impl BackupWriter { h2: H2Client, wid: u64, path: String, - verbose: bool, ) -> (UploadQueueSender, UploadResultReceiver) { let (verify_queue_tx, verify_queue_rx) = mpsc::channel(64); let (verify_result_tx, verify_result_rx) = oneshot::channel(); @@ -491,7 +481,7 @@ impl BackupWriter { digest_list.push(hex::encode(&digest)); offset_list.push(offset); } - if verbose { println!("append chunks list len ({})", digest_list.len()); } + log::debug!("append chunks list len ({})", digest_list.len()); let param = json!({ "wid": wid, "digest-list": digest_list, "offset-list": offset_list }); let request = H2Client::request_builder("localhost", "PUT", &path, None, Some("application/json")).unwrap(); let param_data = bytes::Bytes::from(param.to_string().into_bytes()); @@ -547,13 +537,11 @@ impl BackupWriter { known_chunks.insert(*index.index_digest(i).unwrap()); } - if self.verbose { - println!( - "{}: known chunks list length is {}", - archive_name, - index.index_count() - ); - } + log::debug!( + "{}: known chunks list length is {}", + archive_name, + index.index_count() + ); Ok(index) } @@ -588,13 +576,11 @@ impl BackupWriter { known_chunks.insert(*index.index_digest(i).unwrap()); } - if self.verbose { - println!( - "{}: known chunks list length is {}", - archive_name, - index.index_count() - ); - } + log::debug!( + "{}: known chunks list length is {}", + archive_name, + index.index_count() + ); Ok(index) } @@ -641,7 +627,6 @@ impl BackupWriter { known_chunks: Arc>>, crypt_config: Option>, compress: bool, - verbose: bool, ) -> impl Future> { let total_chunks = Arc::new(AtomicUsize::new(0)); let total_chunks2 = total_chunks.clone(); @@ -660,7 +645,7 @@ impl BackupWriter { let is_fixed_chunk_size = prefix == "fixed"; let (upload_queue, upload_result) = - Self::append_chunk_queue(h2.clone(), wid, append_chunk_path, verbose); + Self::append_chunk_queue(h2.clone(), wid, append_chunk_path); let start_time = std::time::Instant::now(); @@ -721,12 +706,12 @@ impl BackupWriter { let digest = chunk_info.digest; let digest_str = hex::encode(&digest); - /* too verbose, needs finer verbosity setting granularity - if verbose { - println!("upload new chunk {} ({} bytes, offset {})", digest_str, - chunk_info.chunk_len, offset); - } - */ + log::trace!( + "upload new chunk {} ({} bytes, offset {})", + digest_str, + chunk_info.chunk_len, + offset + ); let chunk_data = chunk_info.chunk.into_inner(); let param = json!({ @@ -793,7 +778,7 @@ impl BackupWriter { } /// Upload speed test - prints result to stderr - pub async fn upload_speedtest(&self, verbose: bool) -> Result { + pub async fn upload_speedtest(&self) -> Result { let mut data = vec![]; // generate pseudo random byte sequence for i in 0..1024 * 1024 { @@ -807,7 +792,7 @@ impl BackupWriter { let mut repeat = 0; - let (upload_queue, upload_result) = Self::response_queue(verbose); + let (upload_queue, upload_result) = Self::response_queue(); let start_time = std::time::Instant::now(); @@ -817,9 +802,7 @@ impl BackupWriter { break; } - if verbose { - eprintln!("send test data ({} bytes)", data.len()); - } + log::debug!("send test data ({} bytes)", data.len()); let request = H2Client::request_builder("localhost", "POST", "speedtest", None, None).unwrap(); let request_future = self @@ -834,13 +817,13 @@ impl BackupWriter { let _ = upload_result.await?; - eprintln!( + log::info!( "Uploaded {} chunks in {} seconds.", repeat, start_time.elapsed().as_secs() ); let speed = ((item_len * (repeat as usize)) as f64) / start_time.elapsed().as_secs_f64(); - eprintln!( + log::info!( "Time per request: {} microseconds.", (start_time.elapsed().as_micros()) / (repeat as u128) ); diff --git a/pbs-client/src/catalog_shell.rs b/pbs-client/src/catalog_shell.rs index 85508891..c401e434 100644 --- a/pbs-client/src/catalog_shell.rs +++ b/pbs-client/src/catalog_shell.rs @@ -101,7 +101,7 @@ fn complete_path(complete_me: &str, _map: &HashMap) -> Vec list, Err(err) => { - eprintln!("error during completion: {}", err); + log::error!("error during completion: {}", err); Vec::new() } } @@ -456,7 +456,7 @@ impl Shell { let args = match cli::shellword_split(&line) { Ok(args) => args, Err(err) => { - println!("Error: {}", err); + log::error!("Error: {}", err); continue; } }; diff --git a/pbs-client/src/http_client.rs b/pbs-client/src/http_client.rs index c9104a03..6d5d9ad5 100644 --- a/pbs-client/src/http_client.rs +++ b/pbs-client/src/http_client.rs @@ -347,14 +347,14 @@ impl HttpClient { if let Err(err) = store_fingerprint(prefix.as_ref().unwrap(), &server, &fingerprint) { - eprintln!("{}", err); + log::error!("{}", err); } } *verified_fingerprint.lock().unwrap() = Some(fingerprint); true } Err(err) => { - eprintln!("certificate validation failed - {}", err); + log::error!("certificate validation failed - {}", err); false } }, @@ -457,7 +457,7 @@ impl HttpClient { *auth2.write().unwrap() = auth; } Err(err) => { - eprintln!("re-authentication failed: {}", err); + log::error!("re-authentication failed: {}", err); return; } } @@ -580,14 +580,14 @@ impl HttpClient { if expected_fingerprint == fp_string { return Ok(Some(fp_string)); } else { - eprintln!("WARNING: certificate fingerprint does not match expected fingerprint!"); - eprintln!("expected: {}", expected_fingerprint); + log::warn!("WARNING: certificate fingerprint does not match expected fingerprint!"); + log::warn!("expected: {}", expected_fingerprint); } } // If we're on a TTY, query the user if interactive && tty::stdin_isatty() { - eprintln!("fingerprint: {}", fp_string); + log::info!("fingerprint: {}", fp_string); loop { eprint!("Are you sure you want to continue connecting? (y/n): "); let _ = std::io::stdout().flush(); @@ -775,7 +775,7 @@ impl HttpClient { .handshake(upgraded) .await?; - let connection = connection.map_err(|_| eprintln!("HTTP/2.0 connection failed")); + let connection = connection.map_err(|_| log::error!("HTTP/2.0 connection failed")); let (connection, abort) = futures::future::abortable(connection); // A cancellable future returns an Option which is None when cancelled and diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs index d58bab20..5df324cc 100644 --- a/pbs-client/src/pxar/create.rs +++ b/pbs-client/src/pxar/create.rs @@ -43,8 +43,6 @@ pub struct PxarCreateOptions { pub entries_max: usize, /// Skip lost+found directory pub skip_lost_and_found: bool, - /// Verbose output - pub verbose: bool, } fn detect_fs_type(fd: RawFd) -> Result { diff --git a/pbs-client/src/pxar/extract.rs b/pbs-client/src/pxar/extract.rs index 9a8854c0..95530e48 100644 --- a/pbs-client/src/pxar/extract.rs +++ b/pbs-client/src/pxar/extract.rs @@ -532,12 +532,7 @@ where } /// Creates a tar file from `path` and writes it into `output` -pub async fn create_tar( - output: W, - accessor: Accessor, - path: P, - verbose: bool, -) -> Result<(), Error> +pub async fn create_tar(output: W, accessor: Accessor, path: P) -> Result<(), Error> where T: Clone + pxar::accessor::ReadAt + Unpin + Send + Sync + 'static, W: tokio::io::AsyncWrite + Unpin + Send + 'static, @@ -596,9 +591,7 @@ where let metadata = realfile.entry().metadata(); let realpath = Path::new(link); - if verbose { - eprintln!("adding '{}' to tar", path.display()); - } + log::debug!("adding '{}' to tar", path.display()); let stripped_path = match realpath.strip_prefix(prefix) { Ok(path) => path, @@ -632,9 +625,7 @@ where } } EntryKind::Symlink(link) if !link.data.is_empty() => { - if verbose { - eprintln!("adding '{}' to tar", path.display()); - } + log::debug!("adding '{}' to tar", path.display()); let realpath = Path::new(link); let mut header = tar::Header::new_gnu(); header.set_entry_type(tar::EntryType::Symlink); @@ -646,9 +637,7 @@ where .map_err(|err| format_err!("could not send symlink entry: {}", err))?; } EntryKind::Fifo => { - if verbose { - eprintln!("adding '{}' to tar", path.display()); - } + log::debug!("adding '{}' to tar", path.display()); let mut header = tar::Header::new_gnu(); header.set_entry_type(tar::EntryType::Fifo); add_metadata_to_header(&mut header, metadata); @@ -662,9 +651,7 @@ where .map_err(|err| format_err!("could not send fifo entry: {}", err))?; } EntryKind::Directory => { - if verbose { - eprintln!("adding '{}' to tar", path.display()); - } + log::debug!("adding '{}' to tar", path.display()); // we cannot add the root path itself if path != Path::new("/") { let mut header = tar::Header::new_gnu(); @@ -679,9 +666,7 @@ where } } EntryKind::Device(device) => { - if verbose { - eprintln!("adding '{}' to tar", path.display()); - } + log::debug!("adding '{}' to tar", path.display()); let entry_type = if metadata.stat.is_chardev() { tar::EntryType::Char } else { @@ -704,18 +689,13 @@ where } tarencoder.finish().await.map_err(|err| { - eprintln!("error during finishing of zip: {}", err); + log::error!("error during finishing of zip: {}", err); err })?; Ok(()) } -pub async fn create_zip( - output: W, - accessor: Accessor, - path: P, - verbose: bool, -) -> Result<(), Error> +pub async fn create_zip(output: W, accessor: Accessor, path: P) -> Result<(), Error> where T: Clone + pxar::accessor::ReadAt + Unpin + Send + Sync + 'static, W: tokio::io::AsyncWrite + Unpin + Send + 'static, @@ -758,9 +738,7 @@ where match entry.kind() { EntryKind::File { .. } => { - if verbose { - eprintln!("adding '{}' to zip", path.display()); - } + log::debug!("adding '{}' to zip", path.display()); let entry = ZipEntry::new( path, metadata.stat.mtime.secs, @@ -778,9 +756,7 @@ where .ok_or(format_err!("error looking up '{:?}'", path))?; let realfile = accessor.follow_hardlink(&entry).await?; let metadata = realfile.entry().metadata(); - if verbose { - eprintln!("adding '{}' to zip", path.display()); - } + log::debug!("adding '{}' to zip", path.display()); let entry = ZipEntry::new( path, metadata.stat.mtime.secs, @@ -792,9 +768,7 @@ where .map_err(|err| format_err!("could not send file entry: {}", err))?; } EntryKind::Directory => { - if verbose { - eprintln!("adding '{}' to zip", path.display()); - } + log::debug!("adding '{}' to zip", path.display()); let entry = ZipEntry::new( path, metadata.stat.mtime.secs, @@ -851,7 +825,6 @@ pub async fn extract_sub_dir( destination: DEST, decoder: Accessor, path: PATH, - verbose: bool, ) -> Result<(), Error> where T: Clone + pxar::accessor::ReadAt + Unpin + Send + Sync + 'static, @@ -870,13 +843,12 @@ where .await? .ok_or(format_err!("error opening '{:?}'", path.as_ref()))?; - recurse_files_extractor(&mut extractor, file, verbose).await + recurse_files_extractor(&mut extractor, file).await } pub async fn extract_sub_dir_seq( destination: DEST, mut decoder: Decoder, - verbose: bool, ) -> Result<(), Error> where S: pxar::decoder::SeqRead + Unpin + Send + 'static, @@ -891,8 +863,8 @@ where let mut extractor = get_extractor(destination, root.metadata().clone())?; - if let Err(err) = seq_files_extractor(&mut extractor, decoder, verbose).await { - eprintln!("error extracting pxar archive: {}", err); + if let Err(err) = seq_files_extractor(&mut extractor, decoder).await { + log::error!("error extracting pxar archive: {}", err); } Ok(()) @@ -948,7 +920,6 @@ fn get_filename(entry: &Entry) -> Result<(OsString, CString), Error> { async fn recurse_files_extractor<'a, T>( extractor: &'a mut Extractor, file: FileEntry, - verbose: bool, ) -> Result<(), Error> where T: Clone + pxar::accessor::ReadAt + Unpin + Send + Sync + 'static, @@ -957,9 +928,7 @@ where let metadata = entry.metadata(); let (file_name_os, file_name) = get_filename(entry)?; - if verbose { - eprintln!("extracting: {}", file.path().display()); - } + log::debug!("extracting: {}", file.path().display()); match file.kind() { EntryKind::Directory => { @@ -970,7 +939,7 @@ where let dir = file.enter_directory().await?; let mut seq_decoder = dir.decode_full().await?; seq_decoder.enable_goodbye_entries(true); - seq_files_extractor(extractor, seq_decoder, verbose).await?; + seq_files_extractor(extractor, seq_decoder).await?; extractor.leave_directory()?; } EntryKind::File { size, .. } => { @@ -994,7 +963,6 @@ where async fn seq_files_extractor<'a, T>( extractor: &'a mut Extractor, mut decoder: pxar::decoder::aio::Decoder, - verbose: bool, ) -> Result<(), Error> where T: pxar::decoder::SeqRead, @@ -1009,8 +977,8 @@ where let metadata = entry.metadata(); let (file_name_os, file_name) = get_filename(&entry)?; - if verbose && !matches!(entry.kind(), EntryKind::GoodbyeTable) { - eprintln!("extracting: {}", entry.path().display()); + if !matches!(entry.kind(), EntryKind::GoodbyeTable) { + log::debug!("extracting: {}", entry.path().display()); } if let Err(err) = async { @@ -1044,7 +1012,7 @@ where .await { let display = entry.path().display().to_string(); - eprintln!( + log::error!( "error extracting {}: {}", if matches!(entry.kind(), EntryKind::GoodbyeTable) { "" diff --git a/pbs-client/src/pxar/fuse.rs b/pbs-client/src/pxar/fuse.rs index 594930ef..e9e1b6f3 100644 --- a/pbs-client/src/pxar/fuse.rs +++ b/pbs-client/src/pxar/fuse.rs @@ -240,8 +240,8 @@ impl SessionImpl { /// Here's how we deal with errors: /// - /// Any error will be printed if the verbose flag was set, otherwise the message will be - /// silently dropped. + /// Any error will be logged if a log level of at least 'debug' was set, otherwise the + /// message will be silently dropped. /// /// Opaque errors will cause the fuse main loop to bail out with that error. /// @@ -255,8 +255,8 @@ impl SessionImpl { ) { let final_result = match err.downcast::() { Ok(err) => { - if err.kind() == io::ErrorKind::Other && self.verbose { - eprintln!("an IO error occurred: {}", err); + if err.kind() == io::ErrorKind::Other { + log::error!("an IO error occurred: {}", err); } // fail the request @@ -264,9 +264,7 @@ impl SessionImpl { } Err(err) => { // `bail` (non-`io::Error`) is used for fatal errors which should actually cancel: - if self.verbose { - eprintln!("internal error: {}, bailing out", err); - } + log::error!("internal error: {}, bailing out", err); Err(err) } }; @@ -297,7 +295,7 @@ impl SessionImpl { }, err = err_recv.next() => match err { Some(err) => if self.verbose { - eprintln!("cancelling fuse main loop due to error: {}", err); + log::error!("cancelling fuse main loop due to error: {}", err); return Err(err); }, None => panic!("error channel was closed unexpectedly"), @@ -385,9 +383,7 @@ impl SessionImpl { } } other => { - if self.verbose { - eprintln!("Received unexpected fuse request"); - } + log::error!("Received unexpected fuse request"); other.fail(libc::ENOSYS).map_err(Error::from) } }; diff --git a/pbs-client/src/pxar/metadata.rs b/pbs-client/src/pxar/metadata.rs index 415922ef..22bc5f9d 100644 --- a/pbs-client/src/pxar/metadata.rs +++ b/pbs-client/src/pxar/metadata.rs @@ -208,7 +208,7 @@ fn apply_xattrs( } if !xattr::is_valid_xattr_name(xattr.name()) { - eprintln!("skipping invalid xattr named {:?}", xattr.name()); + log::info!("skipping invalid xattr named {:?}", xattr.name()); continue; } @@ -269,7 +269,7 @@ fn apply_acls( acl.add_entry_full(acl::ACL_GROUP_OBJ, None, mode)?; if !metadata.acl.users.is_empty() || !metadata.acl.groups.is_empty() { - eprintln!( + log::warn!( "Warning: {:?}: Missing GROUP_OBJ entry in ACL, resetting to value of MASK", path_info, ); diff --git a/pbs-client/src/pxar_backup_stream.rs b/pbs-client/src/pxar_backup_stream.rs index 8ffcf36e..22a6ffdc 100644 --- a/pbs-client/src/pxar_backup_stream.rs +++ b/pbs-client/src/pxar_backup_stream.rs @@ -53,17 +53,13 @@ impl PxarBackupStream { StdChannelWriter::new(tx), )); - let verbose = options.verbose; - let writer = pxar::encoder::sync::StandardWriter::new(writer); if let Err(err) = crate::pxar::create_archive( dir, writer, crate::pxar::Flags::DEFAULT, move |path| { - if verbose { - println!("{:?}", path); - } + log::debug!("{:?}", path); Ok(()) }, Some(catalog), diff --git a/pbs-client/src/task_log.rs b/pbs-client/src/task_log.rs index b38ae10c..a396a451 100644 --- a/pbs-client/src/task_log.rs +++ b/pbs-client/src/task_log.rs @@ -31,10 +31,10 @@ pub async fn display_task_log( let abort_future = async move { while signal_stream.recv().await.is_some() { - println!("got shutdown request (SIGINT)"); + log::info!("got shutdown request (SIGINT)"); let prev_count = abort_count2.fetch_add(1, Ordering::SeqCst); if prev_count >= 1 { - println!("forced exit (task still running)"); + log::info!("forced exit (task still running)"); break; } } @@ -77,9 +77,9 @@ pub async fn display_task_log( } if strip_date && t.len() > 27 && &t[25..27] == ": " { let line = &t[27..]; - println!("{}", line); + log::info!("{}", line); } else { - println!("{}", t); + log::info!("{}", t); } start += 1; } diff --git a/pbs-client/src/tools/key_source.rs b/pbs-client/src/tools/key_source.rs index 3ff592e1..f7a8c7fb 100644 --- a/pbs-client/src/tools/key_source.rs +++ b/pbs-client/src/tools/key_source.rs @@ -231,7 +231,7 @@ fn do_crypto_parameters(param: &Value, keep_keyfd_open: bool) -> Result match read_optional_default_encryption_key()? { None => bail!("--crypt-mode without --keyfile and no default key file available"), enc_key => { - eprintln!("Encrypting with default encryption key!"); + log::info!("Encrypting with default encryption key!"); let master_pubkey = match master_pubkey { None => read_optional_default_master_pubkey()?, master_pubkey => master_pubkey, -- 2.39.5