tsarevvv/proxmox-backup
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

pbs-client: replace print with log macro

Browse Source 
Signed-off-by: Hannes Laimer <h.laimer@proxmox.com>
Signed-off-by: Wolfgang Bumiller <w.bumiller@proxmox.com>
This commit is contained in:
Hannes Laimer 2022-06-15 08:19:49 +00:00 committed by Wolfgang Bumiller
parent 955aea8ae8
commit e10fccf5cc
11 changed files with 87 additions and 145 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
pbs-client/Cargo.toml
View File

@ -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"

103
pbs-client/src/backup_writer.rs
View File

@ -28,7 +28,6 @@ use super::{H2Client, HttpClient};
pub struct BackupWriter {
h2: H2Client,
abort: AbortHandle,
verbose: bool,
crypt_config: Option<Arc<CryptConfig>>,
}
@ -66,17 +65,11 @@ type UploadQueueSender = mpsc::Sender<(MergedChunkInfo, Option<h2::client::Respo
type UploadResultReceiver = oneshot::Receiver<Result<(), Error>>;
impl BackupWriter {
fn new(
h2: H2Client,
abort: AbortHandle,
crypt_config: Option<Arc<CryptConfig>>,
verbose: bool,
) -> Arc<Self> {
fn new(h2: H2Client, abort: AbortHandle, crypt_config: Option<Arc<CryptConfig>>) -> Arc<Self> {
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<Value>) -> Result<Value, Error> {
@ -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<h2::client::ResponseFuture>,
oneshot::Receiver<Result<(), Error>>,
) {
@ -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<Mutex<HashSet<[u8; 32]>>>,
crypt_config: Option<Arc<CryptConfig>>,
compress: bool,
verbose: bool,
) -> impl Future<Output = Result<UploadStats, Error>> {
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<f64, Error> {
pub async fn upload_speedtest(&self) -> Result<f64, Error> {
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)
);

4
pbs-client/src/catalog_shell.rs
View File

@ -101,7 +101,7 @@ fn complete_path(complete_me: &str, _map: &HashMap<String, String>) -> Vec<Strin
match shell.complete_path(complete_me) {
Ok(list) => 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;
}
};

14
pbs-client/src/http_client.rs
View File

@ -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

2
pbs-client/src/pxar/create.rs
View File

@ -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<i64, Error> {

70
pbs-client/src/pxar/extract.rs
View File

@ -532,12 +532,7 @@ where
}
/// Creates a tar file from `path` and writes it into `output`
pub async fn create_tar<T, W, P>(
output: W,
accessor: Accessor<T>,
path: P,
verbose: bool,
) -> Result<(), Error>
pub async fn create_tar<T, W, P>(output: W, accessor: Accessor<T>, 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<T, W, P>(
output: W,
accessor: Accessor<T>,
path: P,
verbose: bool,
) -> Result<(), Error>
pub async fn create_zip<T, W, P>(output: W, accessor: Accessor<T>, 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<T, DEST, PATH>(
destination: DEST,
decoder: Accessor<T>,
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<S, DEST>(
destination: DEST,
mut decoder: Decoder<S>,
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<T>,
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<T>,
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) {
"<directory>"

18
pbs-client/src/pxar/fuse.rs
View File

@ -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::<io::Error>() {
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)
}
};

4
pbs-client/src/pxar/metadata.rs
View File

@ -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,
);

6
pbs-client/src/pxar_backup_stream.rs
View File

@ -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),

8
pbs-client/src/task_log.rs
View File

@ -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;
}

2
pbs-client/src/tools/key_source.rs
View File

@ -231,7 +231,7 @@ fn do_crypto_parameters(param: &Value, keep_keyfd_open: bool) -> Result<CryptoPa
(None, master_pubkey) => 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,