[pbs-devel] [PATCH proxmox-backup 06/10] proxmox-backup-client: replace print with log macro

[Hannes Laimer <h.laimer@proxmox.com>]

Signed-off-by: Hannes Laimer <h.laimer@proxmox.com>
---
 proxmox-backup-client/Cargo.toml       |  1 +
 proxmox-backup-client/src/benchmark.rs | 31 +++------
 proxmox-backup-client/src/catalog.rs   |  6 +-
 proxmox-backup-client/src/key.rs       | 27 ++++----
 proxmox-backup-client/src/main.rs      | 95 ++++++++++----------------
 proxmox-backup-client/src/mount.rs     | 12 ++--
 6 files changed, 71 insertions(+), 101 deletions(-)

diff --git a/proxmox-backup-client/Cargo.toml b/proxmox-backup-client/Cargo.toml
index 917a7286..dbd56f97 100644
--- a/proxmox-backup-client/Cargo.toml
+++ b/proxmox-backup-client/Cargo.toml
@@ -9,6 +9,7 @@ anyhow = "1.0"
 futures = "0.3"
 hyper = { version = "0.14", features = [ "full" ] }
 libc = "0.2"
+log = "0.4"
 nix = "0.19.1"
 openssl = "0.10"
 serde = { version = "1.0", features = ["derive"] }
diff --git a/proxmox-backup-client/src/benchmark.rs b/proxmox-backup-client/src/benchmark.rs
index 6a97b117..c518fa05 100644
--- a/proxmox-backup-client/src/benchmark.rs
+++ b/proxmox-backup-client/src/benchmark.rs
@@ -115,11 +115,6 @@ static BENCHMARK_RESULT_2020_TOP: BenchmarkResult =  BenchmarkResult {
                schema: REPO_URL_SCHEMA,
                optional: true,
            },
-           verbose: {
-               description: "Verbose output.",
-               type: bool,
-               optional: true,
-           },
            keyfile: {
                schema: KEYFILE_SCHEMA,
                optional: true,
@@ -142,8 +137,6 @@ pub async fn benchmark(
 
     let keyfile = param["keyfile"].as_str().map(PathBuf::from);
 
-    let verbose = param["verbose"].as_bool().unwrap_or(false);
-
     let output_format = get_output_format(&param);
 
     let crypt_config = match keyfile {
@@ -159,10 +152,10 @@ pub async fn benchmark(
 
     // do repo tests first, because this may prompt for a password
     if let Some(repo) = repo {
-        test_upload_speed(&mut benchmark_result, repo, crypt_config.clone(), verbose).await?;
+        test_upload_speed(&mut benchmark_result, repo, crypt_config.clone()).await?;
     }
 
-    test_crypt_speed(&mut benchmark_result, verbose)?;
+    test_crypt_speed(&mut benchmark_result)?;
 
     render_result(&output_format, &benchmark_result)?;
 
@@ -218,7 +211,6 @@ async fn test_upload_speed(
     benchmark_result: &mut BenchmarkResult,
     repo: BackupRepository,
     crypt_config: Option<Arc<CryptConfig>>,
-    verbose: bool,
 ) -> Result<(), Error> {
 
     let backup_time = proxmox_time::epoch_i64();
@@ -226,7 +218,7 @@ async fn test_upload_speed(
     let client = connect(&repo)?;
     record_repository(&repo);
 
-    if verbose { eprintln!("Connecting to backup server"); }
+    log::debug!("Connecting to backup server");
     let client = BackupWriter::start(
         client,
         crypt_config.clone(),
@@ -238,10 +230,10 @@ async fn test_upload_speed(
         true
     ).await?;
 
-    if verbose { eprintln!("Start TLS speed test"); }
-    let speed = client.upload_speedtest(verbose).await?;
+    log::debug!("Start TLS speed test");
+    let speed = client.upload_speedtest().await?;
 
-    eprintln!("TLS speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("TLS speed: {:.2} MB/s", speed/1_000_000.0);
 
     benchmark_result.tls.speed = Some(speed);
 
@@ -251,7 +243,6 @@ async fn test_upload_speed(
 // test hash/crypt/compress speed
 fn test_crypt_speed(
     benchmark_result: &mut BenchmarkResult,
-    _verbose: bool,
 ) -> Result<(), Error> {
 
     let pw = b"test";
@@ -290,7 +281,7 @@ fn test_crypt_speed(
     let speed = (bytes as f64)/start_time.elapsed().as_secs_f64();
     benchmark_result.sha256.speed = Some(speed);
 
-    eprintln!("SHA256 speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("SHA256 speed: {:.2} MB/s", speed/1_000_000.0);
 
 
     let start_time = std::time::Instant::now();
@@ -305,7 +296,7 @@ fn test_crypt_speed(
     let speed = (bytes as f64)/start_time.elapsed().as_secs_f64();
     benchmark_result.compress.speed = Some(speed);
 
-    eprintln!("Compression speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("Compression speed: {:.2} MB/s", speed/1_000_000.0);
 
 
     let start_time = std::time::Instant::now();
@@ -325,7 +316,7 @@ fn test_crypt_speed(
     let speed = (bytes as f64)/start_time.elapsed().as_secs_f64();
     benchmark_result.decompress.speed = Some(speed);
 
-    eprintln!("Decompress speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("Decompress speed: {:.2} MB/s", speed/1_000_000.0);
 
 
     let start_time = std::time::Instant::now();
@@ -340,7 +331,7 @@ fn test_crypt_speed(
     let speed = (bytes as f64)/start_time.elapsed().as_secs_f64();
     benchmark_result.aes256_gcm.speed = Some(speed);
 
-    eprintln!("AES256/GCM speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("AES256/GCM speed: {:.2} MB/s", speed/1_000_000.0);
 
 
     let start_time = std::time::Instant::now();
@@ -358,7 +349,7 @@ fn test_crypt_speed(
     let speed = (bytes as f64)/start_time.elapsed().as_secs_f64();
     benchmark_result.verify.speed = Some(speed);
 
-    eprintln!("Verify speed: {:.2} MB/s", speed/1_000_000.0);
+    log::info!("Verify speed: {:.2} MB/s", speed/1_000_000.0);
 
     Ok(())
 }
diff --git a/proxmox-backup-client/src/catalog.rs b/proxmox-backup-client/src/catalog.rs
index b0c4eaf0..f7102a78 100644
--- a/proxmox-backup-client/src/catalog.rs
+++ b/proxmox-backup-client/src/catalog.rs
@@ -76,7 +76,7 @@ async fn dump_catalog(param: Value) -> Result<Value, Error> {
         Some(key) => {
             let (key, _created, _fingerprint) = decrypt_key(&key.key, &get_encryption_key_password)
                 .map_err(|err| {
-                    eprintln!("{}", format_key_source(&key.source, "encryption"));
+                    log::error!("{}", format_key_source(&key.source, "encryption"));
                     err
                 })?;
             let crypt_config = CryptConfig::new(key)?;
@@ -178,7 +178,7 @@ async fn catalog_shell(param: Value) -> Result<(), Error> {
         Some(key) => {
             let (key, _created, _fingerprint) = decrypt_key(&key.key, &get_encryption_key_password)
                 .map_err(|err| {
-                    eprintln!("{}", format_key_source(&key.source, "encryption"));
+                    log::error!("{}", format_key_source(&key.source, "encryption"));
                     err
                 })?;
             let crypt_config = CryptConfig::new(key)?;
@@ -252,7 +252,7 @@ async fn catalog_shell(param: Value) -> Result<(), Error> {
         decoder,
     ).await?;
 
-    println!("Starting interactive shell");
+    log::info!("Starting interactive shell");
     state.shell().await?;
 
     record_repository(&repo);
diff --git a/proxmox-backup-client/src/key.rs b/proxmox-backup-client/src/key.rs
index 288d6c67..a9817f20 100644
--- a/proxmox-backup-client/src/key.rs
+++ b/proxmox-backup-client/src/key.rs
@@ -81,7 +81,7 @@ fn create(kdf: Option<Kdf>, path: Option<String>, hint: Option<String>) -> Resul
         Some(path) => PathBuf::from(path),
         None => {
             let path = place_default_encryption_key()?;
-            println!("creating default key at: {:?}", path);
+            log::info!("creating default key at: {:?}", path);
             path
         }
     };
@@ -159,7 +159,7 @@ async fn import_with_master_key(
             if path.exists() {
                 bail!("Please remove default encryption key at {:?} before importing to default location (or choose a non-default one).", path);
             }
-            println!("Importing key to default location at: {:?}", path);
+            log::info!("Importing key to default location at: {:?}", path);
             path
         }
     };
@@ -232,7 +232,7 @@ fn change_passphrase(
             let path = find_default_encryption_key()?.ok_or_else(|| {
                 format_err!("no encryption file provided and no default file found")
             })?;
-            println!("updating default key at: {:?}", path);
+            log::info!("updating default key at: {:?}", path);
             path
         }
     };
@@ -340,10 +340,10 @@ fn import_master_pubkey(path: String) -> Result<(), Error> {
     match openssl::pkey::PKey::public_key_from_pem(&pem_data) {
         Ok(key) => {
             let info = RsaPubKeyInfo::try_from(key.rsa()?)?;
-            println!("Found following key at {:?}", path);
-            println!("Modulus: {}", info.modulus);
-            println!("Exponent: {}", info.exponent);
-            println!("Length: {}", info.length);
+            log::info!("Found following key at {:?}", path);
+            log::info!("Modulus: {}", info.modulus);
+            log::info!("Exponent: {}", info.exponent);
+            log::info!("Length: {}", info.length);
         }
         Err(err) => bail!("Unable to decode PEM data - {}", err),
     };
@@ -352,7 +352,7 @@ fn import_master_pubkey(path: String) -> Result<(), Error> {
 
     replace_file(&target_path, &pem_data, CreateOptions::new(), true)?;
 
-    println!("Imported public master key to {:?}", target_path);
+    log::info!("Imported public master key to {:?}", target_path);
 
     Ok(())
 }
@@ -367,14 +367,13 @@ fn create_master_key() -> Result<(), Error> {
     }
 
     let bits = 4096;
-    println!("Generating {}-bit RSA key..", bits);
+    log::info!("Generating {}-bit RSA key..", bits);
     let rsa = openssl::rsa::Rsa::generate(bits)?;
     let public =
         openssl::rsa::Rsa::from_public_components(rsa.n().to_owned()?, rsa.e().to_owned()?)?;
     let info = RsaPubKeyInfo::try_from(public)?;
-    println!("Modulus: {}", info.modulus);
-    println!("Exponent: {}", info.exponent);
-    println!();
+    log::info!("Modulus: {}", info.modulus);
+    log::info!("Exponent: {}\n", info.exponent);
 
     let pkey = openssl::pkey::PKey::from_rsa(rsa)?;
 
@@ -382,7 +381,7 @@ fn create_master_key() -> Result<(), Error> {
 
     let pub_key: Vec<u8> = pkey.public_key_to_pem()?;
     let filename_pub = "master-public.pem";
-    println!("Writing public master key to {}", filename_pub);
+    log::info!("Writing public master key to {}", filename_pub);
     replace_file(filename_pub, pub_key.as_slice(), CreateOptions::new(), true)?;
 
     let cipher = openssl::symm::Cipher::aes_256_cbc();
@@ -390,7 +389,7 @@ fn create_master_key() -> Result<(), Error> {
         pkey.private_key_to_pem_pkcs8_passphrase(cipher, password.as_bytes())?;
 
     let filename_priv = "master-private.pem";
-    println!("Writing private master key to {}", filename_priv);
+    log::info!("Writing private master key to {}", filename_priv);
     replace_file(filename_priv, priv_key.as_slice(), CreateOptions::new(), true)?;
 
     Ok(())
diff --git a/proxmox-backup-client/src/main.rs b/proxmox-backup-client/src/main.rs
index 744b35e6..6c8a0f75 100644
--- a/proxmox-backup-client/src/main.rs
+++ b/proxmox-backup-client/src/main.rs
@@ -413,7 +413,7 @@ async fn api_version(param: Value) -> Result<(), Error> {
 
         match client.get("api2/json/version", None).await {
             Ok(mut result) => version_info["server"] = result["data"].take(),
-            Err(e) => eprintln!("could not connect to server - {}", e),
+            Err(e) => log::error!("could not connect to server - {}", e),
         }
     }
     if output_format == "text" {
@@ -499,7 +499,7 @@ fn spawn_catalog_upload(
             .await;
 
         if let Err(ref err) = catalog_upload_result {
-            eprintln!("catalog upload error - {}", err);
+            log::error!("catalog upload error - {}", err);
             client.cancel();
         }
 
@@ -605,12 +605,6 @@ fn spawn_catalog_upload(
                optional: true,
                default: pbs_client::pxar::ENCODER_MAX_ENTRIES as isize,
            },
-           "verbose": {
-               type: Boolean,
-               description: "Verbose output.",
-               optional: true,
-               default: false,
-           },
            "dry-run": {
                type: Boolean,
                description: "Just show what backup would do, but do not upload anything.",
@@ -626,7 +620,6 @@ async fn create_backup(
     all_file_systems: bool,
     skip_lost_and_found: bool,
     dry_run: bool,
-    verbose: bool,
     _info: &ApiMethod,
     _rpcenv: &mut dyn RpcEnvironment,
 ) -> Result<Value, Error> {
@@ -781,18 +774,16 @@ async fn create_backup(
     let client = connect_rate_limited(&repo, rate_limit)?;
     record_repository(&repo);
 
-    println!(
+    let start_time = std::time::Instant::now();
+
+    log::info!(
         "Starting backup: {}/{}/{}",
         backup_type,
         backup_id,
         BackupDir::backup_time_to_string(backup_time)?
     );
-
-    println!("Client name: {}", proxmox_sys::nodename());
-
-    let start_time = std::time::Instant::now();
-
-    println!(
+    log::info!("Client name: {}", proxmox_sys::nodename());
+    log::info!(
         "Starting backup protocol: {}",
         strftime_local("%c", epoch_i64())?
     );
@@ -800,20 +791,20 @@ async fn create_backup(
     let (crypt_config, rsa_encrypted_key) = match crypto.enc_key {
         None => (None, None),
         Some(key_with_source) => {
-            println!(
+            log::info!(
                 "{}",
                 format_key_source(&key_with_source.source, "encryption")
             );
 
             let (key, created, fingerprint) =
                 decrypt_key(&key_with_source.key, &get_encryption_key_password)?;
-            println!("Encryption key fingerprint: {}", fingerprint);
+            log::info!("Encryption key fingerprint: {}", fingerprint);
 
             let crypt_config = CryptConfig::new(key)?;
 
             match crypto.master_pubkey {
                 Some(pem_with_source) => {
-                    println!("{}", format_key_source(&pem_with_source.source, "master"));
+                    log::info!("{}", format_key_source(&pem_with_source.source, "master"));
 
                     let rsa = openssl::rsa::Rsa::public_key_from_pem(&pem_with_source.key)?;
 
@@ -836,21 +827,21 @@ async fn create_backup(
         backup_type,
         backup_id,
         backup_time,
-        verbose,
+        true,
         false,
     )
     .await?;
 
     let download_previous_manifest = match client.previous_backup_time().await {
         Ok(Some(backup_time)) => {
-            println!(
+            log::info!(
                 "Downloading previous manifest ({})",
                 strftime_local("%c", backup_time)?
             );
             true
         }
         Ok(None) => {
-            println!("No previous manifest available.");
+            log::info!("No previous manifest available.");
             false
         }
         Err(_) => {
@@ -865,13 +856,13 @@ async fn create_backup(
                 match previous_manifest.check_fingerprint(crypt_config.as_ref().map(Arc::as_ref)) {
                     Ok(()) => Some(Arc::new(previous_manifest)),
                     Err(err) => {
-                        println!("Couldn't re-use previous manifest - {}", err);
+                        log::error!("Couldn't re-use previous manifest - {}", err);
                         None
                     }
                 }
             }
             Err(err) => {
-                println!("Couldn't download previous manifest - {}", err);
+                log::error!("Couldn't download previous manifest - {}", err);
                 None
             }
         }
@@ -887,7 +878,7 @@ async fn create_backup(
 
     let log_file = |desc: &str, file: &str, target: &str| {
         let what = if dry_run { "Would upload" } else { "Upload" };
-        println!("{} {} '{}' to '{}' as {}", what, desc, file, repo, target);
+        log::info!("{} {} '{}' to '{}' as {}", what, desc, file, repo, target);
     };
 
     for (backup_type, filename, target, size) in upload_list {
@@ -946,7 +937,6 @@ async fn create_backup(
                     patterns: pattern_list.clone(),
                     entries_max: entries_max as usize,
                     skip_lost_and_found,
-                    verbose,
                 };
 
                 let upload_options = UploadOptions {
@@ -988,7 +978,7 @@ async fn create_backup(
     }
 
     if dry_run {
-        println!("dry-run: no upload happend");
+        log::info!("dry-run: no upload happend");
         return Ok(Value::Null);
     }
 
@@ -1010,7 +1000,7 @@ async fn create_backup(
 
     if let Some(rsa_encrypted_key) = rsa_encrypted_key {
         let target = ENCRYPTED_KEY_BLOB_NAME;
-        println!("Upload RSA encoded key to '{:?}' as {}", repo, target);
+        log::info!("Upload RSA encoded key to '{:?}' as {}", repo, target);
         let options = UploadOptions {
             compress: false,
             encrypt: false,
@@ -1027,9 +1017,8 @@ async fn create_backup(
         .to_string(crypt_config.as_ref().map(Arc::as_ref))
         .map_err(|err| format_err!("unable to format manifest - {}", err))?;
 
-    if verbose {
-        println!("Upload index.json to '{}'", repo)
-    };
+    log::debug!("Upload index.json to '{}'", repo);
+
     let options = UploadOptions {
         compress: true,
         encrypt: false,
@@ -1043,10 +1032,8 @@ async fn create_backup(
 
     let end_time = std::time::Instant::now();
     let elapsed = end_time.duration_since(start_time);
-    println!("Duration: {:.2}s", elapsed.as_secs_f64());
-
-    println!("End Time: {}", strftime_local("%c", epoch_i64())?);
-
+    log::info!("Duration: {:.2}s", elapsed.as_secs_f64());
+    log::info!("End Time: {}", strftime_local("%c", epoch_i64())?);
     Ok(Value::Null)
 }
 
@@ -1056,7 +1043,6 @@ async fn dump_image<W: Write>(
     crypt_mode: CryptMode,
     index: FixedIndexReader,
     mut writer: W,
-    verbose: bool,
 ) -> Result<(), Error> {
     let most_used = index.find_most_used_chunks(8);
 
@@ -1073,23 +1059,21 @@ async fn dump_image<W: Write>(
         let raw_data = chunk_reader.read_chunk(digest).await?;
         writer.write_all(&raw_data)?;
         bytes += raw_data.len();
-        if verbose {
-            let next_per = ((pos + 1) * 100) / index.index_count();
-            if per != next_per {
-                eprintln!(
-                    "progress {}% (read {} bytes, duration {} sec)",
-                    next_per,
-                    bytes,
-                    start_time.elapsed().as_secs()
-                );
-                per = next_per;
-            }
+        let next_per = ((pos + 1) * 100) / index.index_count();
+        if per != next_per {
+            log::debug!(
+                "progress {}% (read {} bytes, duration {} sec)",
+                next_per,
+                bytes,
+                start_time.elapsed().as_secs()
+            );
+            per = next_per;
         }
     }
 
     let end_time = std::time::Instant::now();
     let elapsed = end_time.duration_since(start_time);
-    eprintln!(
+    log::info!(
         "restore image complete (bytes={}, duration={:.2}s, speed={:.2}MB/s)",
         bytes,
         elapsed.as_secs_f64(),
@@ -1166,8 +1150,6 @@ We do not extract '.pxar' archives when writing to standard output.
 async fn restore(param: Value) -> Result<Value, Error> {
     let repo = extract_repository_from_value(&param)?;
 
-    let verbose = param["verbose"].as_bool().unwrap_or(false);
-
     let allow_existing_dirs = param["allow-existing-dirs"].as_bool().unwrap_or(false);
 
     let archive_name = json::required_string_param(&param, "archive-name")?;
@@ -1210,7 +1192,7 @@ async fn restore(param: Value) -> Result<Value, Error> {
         Some(ref key) => {
             let (key, _, _) =
                 decrypt_key(&key.key, &get_encryption_key_password).map_err(|err| {
-                    eprintln!("{}", format_key_source(&key.source, "encryption"));
+                    log::error!("{}", format_key_source(&key.source, "encryption"));
                     err
                 })?;
             Some(Arc::new(CryptConfig::new(key)?))
@@ -1233,14 +1215,14 @@ async fn restore(param: Value) -> Result<Value, Error> {
     let (manifest, backup_index_data) = client.download_manifest().await?;
 
     if archive_name == ENCRYPTED_KEY_BLOB_NAME && crypt_config.is_none() {
-        eprintln!("Restoring encrypted key blob without original key - skipping manifest fingerprint check!")
+        log::info!("Restoring encrypted key blob without original key - skipping manifest fingerprint check!")
     } else {
         if manifest.signature.is_some() {
             if let Some(key) = &crypto.enc_key {
-                eprintln!("{}", format_key_source(&key.source, "encryption"));
+                log::info!("{}", format_key_source(&key.source, "encryption"));
             }
             if let Some(config) = &crypt_config {
-                eprintln!("Fingerprint: {}", Fingerprint::new(config.fingerprint()));
+                log::info!("Fingerprint: {}", Fingerprint::new(config.fingerprint()));
             }
         }
         manifest.check_fingerprint(crypt_config.as_ref().map(Arc::as_ref))?;
@@ -1310,9 +1292,7 @@ async fn restore(param: Value) -> Result<Value, Error> {
                 Path::new(target),
                 pbs_client::pxar::Flags::DEFAULT,
                 |path| {
-                    if verbose {
-                        println!("{:?}", path);
-                    }
+                    log::debug!("{:?}", path);
                 },
                 options,
             )
@@ -1351,7 +1331,6 @@ async fn restore(param: Value) -> Result<Value, Error> {
             file_info.chunk_crypt_mode(),
             index,
             &mut writer,
-            verbose,
         )
         .await?;
     }
diff --git a/proxmox-backup-client/src/mount.rs b/proxmox-backup-client/src/mount.rs
index 3b0646d5..4b3d089c 100644
--- a/proxmox-backup-client/src/mount.rs
+++ b/proxmox-backup-client/src/mount.rs
@@ -179,9 +179,9 @@ async fn mount_do(param: Value, pipe: Option<Fd>) -> Result<Value, Error> {
     let crypt_config = match keyfile {
         None => None,
         Some(path) => {
-            println!("Encryption key file: '{:?}'", path);
+            log::info!("Encryption key file: '{:?}'", path);
             let (key, _, fingerprint) = load_and_decrypt_key(&path, &get_encryption_key_password)?;
-            println!("Encryption key fingerprint: '{}'", fingerprint);
+            log::info!("Encryption key fingerprint: '{}'", fingerprint);
             Some(Arc::new(CryptConfig::new(key)?))
         }
     };
@@ -308,7 +308,7 @@ async fn mount_do(param: Value, pipe: Option<Fd>) -> Result<Value, Error> {
         }
 
         // daemonize only now to be able to print mapped loopdev or startup errors
-        println!("Image '{}' mapped on {}", name, loopdev);
+        log::info!("Image '{}' mapped on {}", name, loopdev);
         daemonize()?;
 
         // continue polling until complete or interrupted (which also happens on unmap)
@@ -322,7 +322,7 @@ async fn mount_do(param: Value, pipe: Option<Fd>) -> Result<Value, Error> {
             }
         }
 
-        println!("Image unmapped");
+        log::info!("Image unmapped");
     } else {
         bail!("unknown archive file extension (expected .pxar or .img)");
     }
@@ -343,11 +343,11 @@ fn unmap(
             let mut any = false;
             for (backing, loopdev) in pbs_fuse_loop::find_all_mappings()? {
                 let name = proxmox_sys::systemd::unescape_unit(&backing)?;
-                println!("{}:\t{}", loopdev.unwrap_or_else(|| "(unmapped)".to_string()), name);
+                log::info!("{}:\t{}", loopdev.unwrap_or_else(|| "(unmapped)".to_string()), name);
                 any = true;
             }
             if !any {
-                println!("Nothing mapped.");
+                log::info!("Nothing mapped.");
             }
             return Ok(Value::Null);
         },
-- 
2.30.2