From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from firstgate.proxmox.com (firstgate.proxmox.com [212.224.123.68]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by lists.proxmox.com (Postfix) with ESMTPS id D4CED693BA for ; Fri, 11 Mar 2022 16:08:14 +0100 (CET) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id D273926852 for ; Fri, 11 Mar 2022 16:08:14 +0100 (CET) Received: from proxmox-new.maurer-it.com (proxmox-new.maurer-it.com [94.136.29.106]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits)) (No client certificate requested) by firstgate.proxmox.com (Proxmox) with ESMTPS id 8743B2673F for ; Fri, 11 Mar 2022 16:08:08 +0100 (CET) Received: from proxmox-new.maurer-it.com (localhost.localdomain [127.0.0.1]) by proxmox-new.maurer-it.com (Proxmox) with ESMTP id 5A90442135 for ; Fri, 11 Mar 2022 16:08:08 +0100 (CET) From: Hannes Laimer To: pbs-devel@lists.proxmox.com Date: Fri, 11 Mar 2022 15:07:51 +0000 Message-Id: <20220311150755.73338-7-h.laimer@proxmox.com> X-Mailer: git-send-email 2.30.2 In-Reply-To: <20220311150755.73338-1-h.laimer@proxmox.com> References: <20220311150755.73338-1-h.laimer@proxmox.com> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-SPAM-LEVEL: Spam detection results: 0 AWL 0.040 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_PASS -0.001 SPF: sender matches SPF record T_SCC_BODY_TEXT_LINE -0.01 - Subject: [pbs-devel] [PATCH proxmox-backup 06/10] proxmox-backup-client: replace print with log macro X-BeenThere: pbs-devel@lists.proxmox.com X-Mailman-Version: 2.1.29 Precedence: list List-Id: Proxmox Backup Server development discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 11 Mar 2022 15:08:14 -0000 Signed-off-by: Hannes Laimer --- 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(¶m); 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>, - 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 { 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, path: Option, hint: Option) -> 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 = 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 { @@ -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( 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( 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 { let repo = extract_repository_from_value(¶m)?; - 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(¶m, "archive-name")?; @@ -1210,7 +1192,7 @@ async fn restore(param: Value) -> Result { 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 { 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 { 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 { 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) -> Result { 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) -> Result { } // 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) -> Result { } } - 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