[PATCH proxmox-backup 0/6] fix #7024: add more information inside backup logs

[PATCH proxmox-backup 0/6] fix #7024: add more information inside backup logs

[Shan Shaji]

This series addresses three issues:
- File number statistics not being shown under change detection summary for data and
  legacy mode.
- The pogress logs were not showing the number of processed files.
- There was no verbose option.

Changes since RFC: Thanks to @Christian Ebner
  - Patch 2/6: Add more helper functions to PxarArchiverProgressStats
    and change their visibility to pub(crate).
  - Patch 3/6: Use the new helper functions to show the summary for
    both legacy mode and data mode.
  - Patch 4/6: Add a preparatory patch for sharing UploadCounters
    inside the progress logger callback used in patch 5/6.
  - Patch 5/6: Instead of passing PxarArchiverProgressStats around,
    add a callback to UploadOptions that accepts UploadCounters and
    TimeSpan as parameters. At the UploadOptions creation site, a
    closure can then be passed that takes the pxar archiver stats and
    logs the output.
  - Patch 6/6: Instead of switching the log level based on the verbose
    flag, bump the log level to info and gate the output behind the
    verbose flag.
  - Reword and fix some commit body messages. 

Shan Shaji (6):
  client: pxar: rename `ReuseStats` struct to PxarArchiverProgressStats
  client: pxar:  use atomic values in `PxarArchiverProgressStats`
  fix #7024: pxar: show archiver summary for legacy and data mode
  client: backup_stats: move `uploaded_len` counter to `UploadCounters`
  fix #7024: cli: add more information inside the backup progress logs
  fix #7024: cli: add option to enable verbose logs

 pbs-client/src/backup_stats.rs                |  16 +-
 pbs-client/src/backup_writer.rs               |  43 ++---
 pbs-client/src/lib.rs                         |   2 +-
 pbs-client/src/pxar/create.rs                 | 179 ++++++++++++++----
 pbs-client/src/pxar/mod.rs                    |   3 +-
 pbs-client/src/pxar/tools.rs                  |   9 +-
 pbs-client/src/pxar_backup_stream.rs          |  13 +-
 proxmox-backup-client/src/main.rs             |  65 ++++++-
 .../src/proxmox_restore_daemon/api.rs         |   2 +
 pxar-bin/src/main.rs                          |   2 +
 tests/catar.rs                                |   1 +
 11 files changed, 260 insertions(+), 75 deletions(-)

-- 
2.47.3

[PATCH proxmox-backup 1/6] client: pxar: rename `ReuseStats` struct to PxarArchiverProgressStats

[Shan Shaji]

Earlier, the `ReuseStats` struct was used to count and show summary for
metadata mode. Since, the same counter will be used to show stats for
both legacy and data mode, rename `ReuseStats` struct to
`PxarArchiverProgressStats` and its corresponding property inside the
`Archiver` to `progress_stats`.

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/pxar/create.rs | 46 +++++++++++++++++------------------
 1 file changed, 23 insertions(+), 23 deletions(-)

diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs
index cb66b70b8..ab2b9301c 100644
--- a/pbs-client/src/pxar/create.rs
+++ b/pbs-client/src/pxar/create.rs
@@ -150,7 +150,7 @@ pub(crate) struct HardLinkInfo {
 }
 
 #[derive(Default)]
-struct ReuseStats {
+struct PxarArchiverProgressStats {
     files_reused_count: u64,
     files_hardlink_count: u64,
     files_reencoded_count: u64,
@@ -193,7 +193,7 @@ struct Archiver {
     // an older client without the encode-time check is detected here and the affected file is
     // re-encoded instead of reused.
     last_reusable_offset: Option<u64>,
-    reuse_stats: ReuseStats,
+    progress_stats: PxarArchiverProgressStats,
     split_archive: bool,
 }
 
@@ -304,7 +304,7 @@ where
         previous_payload_index,
         cache: PxarLookaheadCache::new(options.max_cache_size),
         last_reusable_offset: None,
-        reuse_stats: ReuseStats::default(),
+        progress_stats: PxarArchiverProgressStats::default(),
         split_archive,
     };
 
@@ -325,28 +325,28 @@ where
         info!("Change detection summary:");
         info!(
             " - {} total files ({} hardlinks)",
-            archiver.reuse_stats.files_reused_count
-                + archiver.reuse_stats.files_reencoded_count
-                + archiver.reuse_stats.files_hardlink_count,
-            archiver.reuse_stats.files_hardlink_count,
+            archiver.progress_stats.files_reused_count
+                + archiver.progress_stats.files_reencoded_count
+                + archiver.progress_stats.files_hardlink_count,
+            archiver.progress_stats.files_hardlink_count,
         );
         info!(
             " - {} unchanged, reusable files with {} data",
-            archiver.reuse_stats.files_reused_count,
-            HumanByte::from(archiver.reuse_stats.total_reused_payload_size),
+            archiver.progress_stats.files_reused_count,
+            HumanByte::from(archiver.progress_stats.total_reused_payload_size),
         );
         info!(
             " - {} changed or non-reusable files with {} data",
-            archiver.reuse_stats.files_reencoded_count,
-            HumanByte::from(archiver.reuse_stats.total_reencoded_size),
+            archiver.progress_stats.files_reencoded_count,
+            HumanByte::from(archiver.progress_stats.total_reencoded_size),
         );
         info!(
             " - {} padding in {} partially reused chunks",
             HumanByte::from(
-                archiver.reuse_stats.total_injected_size
-                    - archiver.reuse_stats.total_reused_payload_size
+                archiver.progress_stats.total_injected_size
+                    - archiver.progress_stats.total_reused_payload_size
             ),
-            archiver.reuse_stats.partial_chunks_count,
+            archiver.progress_stats.partial_chunks_count,
         );
     }
     Ok(())
@@ -968,24 +968,24 @@ impl Archiver {
                 }
 
                 let offset: LinkOffset = if let Some(payload_offset) = payload_offset {
-                    self.reuse_stats.total_reused_payload_size +=
+                    self.progress_stats.total_reused_payload_size +=
                         file_size + size_of::<pxar::format::Header>() as u64;
-                    self.reuse_stats.files_reused_count += 1;
+                    self.progress_stats.files_reused_count += 1;
 
                     encoder
                         .add_payload_ref(metadata, file_name, file_size, payload_offset)
                         .await?
                 } else {
-                    self.reuse_stats.total_reencoded_size +=
+                    self.progress_stats.total_reencoded_size +=
                         file_size + size_of::<pxar::format::Header>() as u64;
-                    self.reuse_stats.files_reencoded_count += 1;
+                    self.progress_stats.files_reencoded_count += 1;
 
                     self.add_regular_file(encoder, fd, file_name, metadata, file_size)
                         .await?
                 };
 
                 if stat.st_nlink > 1 {
-                    self.reuse_stats.files_hardlink_count += 1;
+                    self.progress_stats.files_hardlink_count += 1;
                     self.hardlinks
                         .insert(link_info, (self.path.clone(), offset));
                 }
@@ -1212,11 +1212,11 @@ impl Archiver {
                     HumanByte::from(chunk.padding),
                     HumanByte::from(chunk.size()),
                 );
-                self.reuse_stats.total_injected_size += chunk.size();
-                self.reuse_stats.total_injected_count += 1;
+                self.progress_stats.total_injected_size += chunk.size();
+                self.progress_stats.total_injected_count += 1;
 
                 if chunk.padding > 0 {
-                    self.reuse_stats.partial_chunks_count += 1;
+                    self.progress_stats.partial_chunks_count += 1;
                 }
 
                 size = size.add(chunk.size());
@@ -2072,7 +2072,7 @@ mod tests {
                 suggested_boundaries: Some(suggested_boundaries),
                 cache: PxarLookaheadCache::new(None),
                 last_reusable_offset: None,
-                reuse_stats: ReuseStats::default(),
+                progress_stats: PxarArchiverProgressStats::default(),
                 split_archive: true,
             };
 
-- 
2.47.3

[PATCH proxmox-backup 2/6] client: pxar: use atomic values in `PxarArchiverProgressStats`

[Shan Shaji]

Make all fields of the PxarArchiverProgressStats struct atomic.
This is in preparation to enable lock free access of the archiver stats
from within the progress logger callback.

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/pxar/create.rs | 132 +++++++++++++++++++++++++---------
 1 file changed, 98 insertions(+), 34 deletions(-)

diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs
index ab2b9301c..bde66ac2d 100644
--- a/pbs-client/src/pxar/create.rs
+++ b/pbs-client/src/pxar/create.rs
@@ -7,6 +7,7 @@ use std::ops::Range;
 use std::os::unix::ffi::OsStrExt;
 use std::os::unix::io::{AsRawFd, FromRawFd, IntoRawFd, OwnedFd, RawFd};
 use std::path::{Path, PathBuf};
+use std::sync::atomic::{AtomicU64, Ordering};
 use std::sync::{Arc, Mutex, mpsc};
 
 use anyhow::{Context, Error, bail};
@@ -151,14 +152,89 @@ pub(crate) struct HardLinkInfo {
 
 #[derive(Default)]
 struct PxarArchiverProgressStats {
-    files_reused_count: u64,
-    files_hardlink_count: u64,
-    files_reencoded_count: u64,
-    total_injected_count: u64,
-    partial_chunks_count: u64,
-    total_injected_size: u64,
-    total_reused_payload_size: u64,
-    total_reencoded_size: u64,
+    files_reused_count: AtomicU64,
+    files_hardlink_count: AtomicU64,
+    files_reencoded_count: AtomicU64,
+    total_injected_count: AtomicU64,
+    partial_chunks_count: AtomicU64,
+    total_injected_size: AtomicU64,
+    total_reused_payload_size: AtomicU64,
+    total_reencoded_size: AtomicU64,
+}
+
+impl PxarArchiverProgressStats {
+    #[inline(always)]
+    pub(crate) fn files_reencoded_count(&self) -> u64 {
+        self.files_reencoded_count.load(Ordering::Acquire)
+    }
+
+    #[inline(always)]
+    pub(crate) fn total_reencoded_size(&self) -> u64 {
+        self.total_reencoded_size.load(Ordering::Acquire)
+    }
+
+    #[inline(always)]
+    pub(crate) fn files_reused_count(&self) -> u64 {
+        self.files_reused_count.load(Ordering::Acquire)
+    }
+
+    #[inline(always)]
+    pub(crate) fn total_reused_payload_size(&self) -> u64 {
+        self.total_reused_payload_size.load(Ordering::Acquire)
+    }
+
+    fn padding(&self) -> u64 {
+        self.total_injected_size.load(Ordering::Acquire) - self.total_reused_payload_size()
+    }
+
+    #[inline(always)]
+    fn total_hardlink_count(&self) -> u64 {
+        self.files_hardlink_count.load(Ordering::Acquire)
+    }
+
+    fn partial_chunks_count(&self) -> u64 {
+        self.partial_chunks_count.load(Ordering::Acquire)
+    }
+
+    #[inline(always)]
+    pub(crate) fn total_files_processed(&self) -> u64 {
+        self.files_reused_count() + self.total_hardlink_count() + self.files_reencoded_count()
+    }
+
+    #[inline(always)]
+    fn increment_reused_payload_size(&self, file_size: u64) {
+        self.total_reused_payload_size.fetch_add(
+            file_size + size_of::<pxar::format::Header>() as u64,
+            Ordering::Release,
+        );
+        self.files_reused_count.fetch_add(1, Ordering::Release);
+    }
+
+    #[inline(always)]
+    fn increment_reencoded_size(&self, file_size: u64) {
+        self.total_reencoded_size.fetch_add(
+            file_size + size_of::<pxar::format::Header>() as u64,
+            Ordering::Release,
+        );
+        self.files_reencoded_count.fetch_add(1, Ordering::Release);
+    }
+
+    #[inline(always)]
+    fn increment_hardlink_count(&self) {
+        self.files_hardlink_count.fetch_add(1, Ordering::Release);
+    }
+
+    #[inline(always)]
+    fn increment_partial_chunk_count(&self) {
+        self.partial_chunks_count.fetch_add(1, Ordering::Release);
+    }
+
+    #[inline(always)]
+    fn increment_injected_size(&self, chunk_size: u64) {
+        self.total_injected_size
+            .fetch_add(chunk_size, Ordering::Release);
+        self.total_injected_count.fetch_add(1, Ordering::Release);
+    }
 }
 
 #[derive(Serialize, Deserialize)]
@@ -325,30 +401,26 @@ where
         info!("Change detection summary:");
         info!(
             " - {} total files ({} hardlinks)",
-            archiver.progress_stats.files_reused_count
-                + archiver.progress_stats.files_reencoded_count
-                + archiver.progress_stats.files_hardlink_count,
-            archiver.progress_stats.files_hardlink_count,
+            archiver.progress_stats.total_files_processed(),
+            archiver.progress_stats.total_hardlink_count(),
         );
         info!(
             " - {} unchanged, reusable files with {} data",
-            archiver.progress_stats.files_reused_count,
-            HumanByte::from(archiver.progress_stats.total_reused_payload_size),
+            archiver.progress_stats.files_reused_count(),
+            HumanByte::from(archiver.progress_stats.total_reused_payload_size()),
         );
         info!(
             " - {} changed or non-reusable files with {} data",
-            archiver.progress_stats.files_reencoded_count,
-            HumanByte::from(archiver.progress_stats.total_reencoded_size),
+            archiver.progress_stats.files_reencoded_count(),
+            HumanByte::from(archiver.progress_stats.total_reencoded_size()),
         );
         info!(
             " - {} padding in {} partially reused chunks",
-            HumanByte::from(
-                archiver.progress_stats.total_injected_size
-                    - archiver.progress_stats.total_reused_payload_size
-            ),
-            archiver.progress_stats.partial_chunks_count,
+            HumanByte::from(archiver.progress_stats.padding()),
+            archiver.progress_stats.partial_chunks_count(),
         );
     }
+
     Ok(())
 }
 
@@ -968,24 +1040,18 @@ impl Archiver {
                 }
 
                 let offset: LinkOffset = if let Some(payload_offset) = payload_offset {
-                    self.progress_stats.total_reused_payload_size +=
-                        file_size + size_of::<pxar::format::Header>() as u64;
-                    self.progress_stats.files_reused_count += 1;
-
+                    self.progress_stats.increment_reused_payload_size(file_size);
                     encoder
                         .add_payload_ref(metadata, file_name, file_size, payload_offset)
                         .await?
                 } else {
-                    self.progress_stats.total_reencoded_size +=
-                        file_size + size_of::<pxar::format::Header>() as u64;
-                    self.progress_stats.files_reencoded_count += 1;
-
+                    self.progress_stats.increment_reencoded_size(file_size);
                     self.add_regular_file(encoder, fd, file_name, metadata, file_size)
                         .await?
                 };
 
                 if stat.st_nlink > 1 {
-                    self.progress_stats.files_hardlink_count += 1;
+                    self.progress_stats.increment_hardlink_count();
                     self.hardlinks
                         .insert(link_info, (self.path.clone(), offset));
                 }
@@ -1212,11 +1278,9 @@ impl Archiver {
                     HumanByte::from(chunk.padding),
                     HumanByte::from(chunk.size()),
                 );
-                self.progress_stats.total_injected_size += chunk.size();
-                self.progress_stats.total_injected_count += 1;
-
+                self.progress_stats.increment_injected_size(chunk.size());
                 if chunk.padding > 0 {
-                    self.progress_stats.partial_chunks_count += 1;
+                    self.progress_stats.increment_partial_chunk_count();
                 }
 
                 size = size.add(chunk.size());
-- 
2.47.3

[PATCH proxmox-backup 3/6] fix #7024: pxar: show archiver summary for legacy and data mode

[Shan Shaji]

earlier, the archiver summary was only being shown when the change
detection mode is metadata. To improve this, log the total number of
files and the amount of data re-encoded for legacy and data modes
as well.

Fixes: https://bugzilla.proxmox.com/show_bug.cgi?id=7024

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/pxar/create.rs | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs
index bde66ac2d..ed7ca92f2 100644
--- a/pbs-client/src/pxar/create.rs
+++ b/pbs-client/src/pxar/create.rs
@@ -419,6 +419,14 @@ where
             HumanByte::from(archiver.progress_stats.padding()),
             archiver.progress_stats.partial_chunks_count(),
         );
+    } else {
+        info!("Processing summary:");
+        info!(
+            "- {} total files ({} hardlinks) with {} data",
+            archiver.progress_stats.total_files_processed(),
+            archiver.progress_stats.total_hardlink_count(),
+            HumanByte::from(archiver.progress_stats.total_reencoded_size()),
+        );
     }
 
     Ok(())
-- 
2.47.3

[PATCH proxmox-backup 4/6] client: backup_stats: move `uploaded_len` counter to `UploadCounters`

[Shan Shaji]

earlier the uploaded size was tracked using `uploaded_len` Arc counter.
Since the uploaded size needs to be accessible inside the progress logs
in the later commit, move the `uploaded_len` field to `UploadCounters`.

This was done, in order to avoid passing the variable as a separate
parameter through the callback.

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/backup_stats.rs  | 12 ++++++++++++
 pbs-client/src/backup_writer.rs | 12 +++++-------
 2 files changed, 17 insertions(+), 7 deletions(-)

diff --git a/pbs-client/src/backup_stats.rs b/pbs-client/src/backup_stats.rs
index d7c13784b..6aceee331 100644
--- a/pbs-client/src/backup_stats.rs
+++ b/pbs-client/src/backup_stats.rs
@@ -50,6 +50,7 @@ pub(crate) struct UploadCounters {
     injected_stream_len: Arc<AtomicUsize>,
     reused_stream_len: Arc<AtomicUsize>,
     total_stream_len: Arc<AtomicUsize>,
+    uploaded_len: Arc<AtomicUsize>,
 }
 
 impl UploadCounters {
@@ -63,6 +64,7 @@ impl UploadCounters {
             injected_stream_len: Arc::new(AtomicUsize::new(0)),
             reused_stream_len: Arc::new(AtomicUsize::new(0)),
             total_stream_len: Arc::new(AtomicUsize::new(0)),
+            uploaded_len: Arc::new(AtomicUsize::new(0)),
         }
     }
 
@@ -101,6 +103,16 @@ impl UploadCounters {
         self.total_stream_len.load(Ordering::SeqCst)
     }
 
+    #[inline(always)]
+    pub(crate) fn add_uploaded_len(&mut self, size: usize) {
+        self.uploaded_len.fetch_add(size, Ordering::SeqCst);
+    }
+
+    #[inline(always)]
+    pub fn uploaded_len(&self) -> usize {
+        self.uploaded_len.load(Ordering::SeqCst)
+    }
+
     /// Convert the counters to [`UploadStats`], including given archive checksum and runtime.
     #[inline(always)]
     pub(crate) fn to_upload_stats(&self, csum: [u8; 32], duration: Duration) -> UploadStats {
diff --git a/pbs-client/src/backup_writer.rs b/pbs-client/src/backup_writer.rs
index f0744ecaf..34d8db90b 100644
--- a/pbs-client/src/backup_writer.rs
+++ b/pbs-client/src/backup_writer.rs
@@ -1,6 +1,5 @@
 use std::collections::HashSet;
 use std::future::Future;
-use std::sync::atomic::{AtomicUsize, Ordering};
 use std::sync::{Arc, Mutex};
 use std::time::Instant;
 
@@ -588,7 +587,7 @@ impl BackupWriter {
         h2: H2Client,
         wid: u64,
         path: String,
-        uploaded: Arc<AtomicUsize>,
+        upload_counters: UploadCounters,
     ) -> (UploadQueueSender, UploadResultReceiver) {
         let (verify_queue_tx, verify_queue_rx) = mpsc::channel(64);
         let (verify_result_tx, verify_result_rx) = oneshot::channel();
@@ -606,10 +605,10 @@ impl BackupWriter {
                                     .map_err(Error::from)
                                     .and_then(H2Client::h2api_response)
                                     .and_then({
-                                        let uploaded = uploaded.clone();
+                                        let mut counters = upload_counters.clone();
                                         move |_result| {
                                             // account for uploaded bytes for progress output
-                                            uploaded.fetch_add(response.size, Ordering::SeqCst);
+                                            counters.add_uploaded_len(response.size);
                                             future::ok(MergedChunkInfo::Known(list))
                                         }
                                     })
@@ -871,10 +870,9 @@ impl BackupWriter {
         let upload_chunk_path = format!("{prefix}_chunk");
 
         let start_time = std::time::Instant::now();
-        let uploaded_len = Arc::new(AtomicUsize::new(0));
 
         let (upload_queue, upload_result) =
-            Self::append_chunk_queue(h2.clone(), wid, append_chunk_path, uploaded_len.clone());
+            Self::append_chunk_queue(h2.clone(), wid, append_chunk_path, counters.clone());
 
         let progress_handle = if archive.ends_with(".img.fidx")
             || archive.ends_with(".pxar.didx")
@@ -886,7 +884,7 @@ impl BackupWriter {
                     tokio::time::sleep(tokio::time::Duration::from_secs(60)).await;
 
                     let size = HumanByte::from(counters.total_stream_len());
-                    let size_uploaded = HumanByte::from(uploaded_len.load(Ordering::SeqCst));
+                    let size_uploaded = HumanByte::from(counters.uploaded_len());
                     let elapsed = TimeSpan::from(start_time.elapsed());
 
                     info!("processed {size} in {elapsed}, uploaded {size_uploaded}");
-- 
2.47.3

[PATCH proxmox-backup 5/6] fix #7024: cli: add more information inside the backup progress logs

[Shan Shaji]

previously, the progress logs only reported the processed stream size
and uploaded size. To improve visibility additional information from
`PxarArchiverProgressStats` and `UploadCounters` has been included in
the logs.

To access the upload statistics, a new callback field has been added to
the UploadOptions struct that accepts UploadCounters and TimeSpan as
parameters. Additionally, to include pxar metadata in the logs, the
`PxarArchiverProgressStats` instance is now created earlier and shared
between the archiver and the progress logger callback.

Fixes: https://bugzilla.proxmox.com/show_bug.cgi?id=7024

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/backup_stats.rs                |  4 +-
 pbs-client/src/backup_writer.rs               | 24 ++++-----
 pbs-client/src/lib.rs                         |  2 +-
 pbs-client/src/pxar/create.rs                 | 17 +++---
 pbs-client/src/pxar/mod.rs                    |  3 +-
 pbs-client/src/pxar_backup_stream.rs          | 13 ++++-
 proxmox-backup-client/src/main.rs             | 53 +++++++++++++++++--
 .../src/proxmox_restore_daemon/api.rs         |  1 +
 pxar-bin/src/main.rs                          |  1 +
 tests/catar.rs                                |  1 +
 10 files changed, 89 insertions(+), 30 deletions(-)

diff --git a/pbs-client/src/backup_stats.rs b/pbs-client/src/backup_stats.rs
index 6aceee331..a1dc7ea7b 100644
--- a/pbs-client/src/backup_stats.rs
+++ b/pbs-client/src/backup_stats.rs
@@ -42,7 +42,7 @@ impl UploadStats {
 
 /// Atomic counters for accounting upload stream progress information
 #[derive(Clone)]
-pub(crate) struct UploadCounters {
+pub struct UploadCounters {
     injected_chunk_count: Arc<AtomicUsize>,
     known_chunk_count: Arc<AtomicUsize>,
     total_chunk_count: Arc<AtomicUsize>,
@@ -99,7 +99,7 @@ impl UploadCounters {
     }
 
     #[inline(always)]
-    pub(crate) fn total_stream_len(&self) -> usize {
+    pub fn total_stream_len(&self) -> usize {
         self.total_stream_len.load(Ordering::SeqCst)
     }
 
diff --git a/pbs-client/src/backup_writer.rs b/pbs-client/src/backup_writer.rs
index 34d8db90b..8ae0cffe8 100644
--- a/pbs-client/src/backup_writer.rs
+++ b/pbs-client/src/backup_writer.rs
@@ -45,6 +45,8 @@ impl Drop for BackupWriter {
     }
 }
 
+type ProgressLoggerCallback = Box<dyn Fn(&UploadCounters, &TimeSpan) + Send + Sync>;
+
 /// Options for uploading blobs/streams to the server
 #[derive(Default, Clone)]
 pub struct UploadOptions {
@@ -52,6 +54,7 @@ pub struct UploadOptions {
     pub compress: bool,
     pub encrypt: bool,
     pub index_type: IndexType,
+    pub progress_logging_callback: Option<Arc<ProgressLoggerCallback>>,
 }
 
 /// Index type for upload options.
@@ -371,11 +374,11 @@ impl BackupWriter {
         let upload_stats = Self::upload_merged_chunk_stream(
             self.h2.clone(),
             wid,
-            archive_name,
             prefix,
             stream,
             index_csum_2,
             counters_readonly,
+            options.progress_logging_callback,
         )
         .await?;
 
@@ -476,7 +479,7 @@ impl BackupWriter {
             },
             options.compress,
             injections,
-            archive_name,
+            options.progress_logging_callback,
         )
         .await?;
 
@@ -768,7 +771,7 @@ impl BackupWriter {
         crypt_config: Option<Arc<CryptConfig>>,
         compress: bool,
         injections: Option<std::sync::mpsc::Receiver<InjectChunks>>,
-        archive: &BackupArchiveName,
+        progress_logging_callback: Option<Arc<ProgressLoggerCallback>>,
     ) -> impl Future<Output = Result<UploadStats, Error>> {
         let mut counters = UploadCounters::new();
         let counters_readonly = counters.clone();
@@ -849,22 +852,22 @@ impl BackupWriter {
         Self::upload_merged_chunk_stream(
             h2,
             wid,
-            archive,
             prefix,
             stream,
             index_csum_2,
             counters_readonly,
+            progress_logging_callback,
         )
     }
 
     fn upload_merged_chunk_stream(
         h2: H2Client,
         wid: u64,
-        archive: &BackupArchiveName,
         prefix: &str,
         stream: impl Stream<Item = Result<MergedChunkInfo, Error>>,
         index_csum: Arc<Mutex<Option<Sha256>>>,
         counters: UploadCounters,
+        progress_logging_callback: Option<Arc<ProgressLoggerCallback>>,
     ) -> impl Future<Output = Result<UploadStats, Error>> {
         let append_chunk_path = format!("{prefix}_index");
         let upload_chunk_path = format!("{prefix}_chunk");
@@ -874,20 +877,13 @@ impl BackupWriter {
         let (upload_queue, upload_result) =
             Self::append_chunk_queue(h2.clone(), wid, append_chunk_path, counters.clone());
 
-        let progress_handle = if archive.ends_with(".img.fidx")
-            || archive.ends_with(".pxar.didx")
-            || archive.ends_with(".ppxar.didx")
-        {
+        let progress_handle = if let Some(callback) = progress_logging_callback {
             let counters = counters.clone();
             Some(tokio::spawn(async move {
                 loop {
                     tokio::time::sleep(tokio::time::Duration::from_secs(60)).await;
-
-                    let size = HumanByte::from(counters.total_stream_len());
-                    let size_uploaded = HumanByte::from(counters.uploaded_len());
                     let elapsed = TimeSpan::from(start_time.elapsed());
-
-                    info!("processed {size} in {elapsed}, uploaded {size_uploaded}");
+                    callback(&counters, &elapsed);
                 }
             }))
         } else {
diff --git a/pbs-client/src/lib.rs b/pbs-client/src/lib.rs
index 139f4f4b5..6bf6cc4e6 100644
--- a/pbs-client/src/lib.rs
+++ b/pbs-client/src/lib.rs
@@ -43,7 +43,7 @@ mod chunk_stream;
 pub use chunk_stream::{ChunkStream, FixedChunkStream, InjectionData};
 
 mod backup_stats;
-pub use backup_stats::BackupStats;
+pub use backup_stats::{BackupStats, UploadCounters};
 
 mod log_throttle;
 pub use log_throttle::LogThrottle;
diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs
index ed7ca92f2..7012a88dd 100644
--- a/pbs-client/src/pxar/create.rs
+++ b/pbs-client/src/pxar/create.rs
@@ -151,7 +151,7 @@ pub(crate) struct HardLinkInfo {
 }
 
 #[derive(Default)]
-struct PxarArchiverProgressStats {
+pub struct PxarArchiverProgressStats {
     files_reused_count: AtomicU64,
     files_hardlink_count: AtomicU64,
     files_reencoded_count: AtomicU64,
@@ -169,17 +169,17 @@ impl PxarArchiverProgressStats {
     }
 
     #[inline(always)]
-    pub(crate) fn total_reencoded_size(&self) -> u64 {
+    pub fn total_reencoded_size(&self) -> u64 {
         self.total_reencoded_size.load(Ordering::Acquire)
     }
 
     #[inline(always)]
-    pub(crate) fn files_reused_count(&self) -> u64 {
+    pub fn files_reused_count(&self) -> u64 {
         self.files_reused_count.load(Ordering::Acquire)
     }
 
     #[inline(always)]
-    pub(crate) fn total_reused_payload_size(&self) -> u64 {
+    pub fn total_reused_payload_size(&self) -> u64 {
         self.total_reused_payload_size.load(Ordering::Acquire)
     }
 
@@ -197,7 +197,7 @@ impl PxarArchiverProgressStats {
     }
 
     #[inline(always)]
-    pub(crate) fn total_files_processed(&self) -> u64 {
+    pub fn total_files_processed(&self) -> u64 {
         self.files_reused_count() + self.total_hardlink_count() + self.files_reencoded_count()
     }
 
@@ -269,7 +269,7 @@ struct Archiver {
     // an older client without the encode-time check is detected here and the affected file is
     // re-encoded instead of reused.
     last_reusable_offset: Option<u64>,
-    progress_stats: PxarArchiverProgressStats,
+    progress_stats: Arc<PxarArchiverProgressStats>,
     split_archive: bool,
 }
 
@@ -297,6 +297,7 @@ pub async fn create_archive<T, F>(
     options: PxarCreateOptions,
     forced_boundaries: Option<mpsc::Sender<InjectChunks>>,
     suggested_boundaries: Option<mpsc::Sender<u64>>,
+    archiver_progress_stats: Option<Arc<PxarArchiverProgressStats>>,
 ) -> Result<(), Error>
 where
     T: SeqWrite + Send,
@@ -380,7 +381,7 @@ where
         previous_payload_index,
         cache: PxarLookaheadCache::new(options.max_cache_size),
         last_reusable_offset: None,
-        progress_stats: PxarArchiverProgressStats::default(),
+        progress_stats: archiver_progress_stats.unwrap_or_default(),
         split_archive,
     };
 
@@ -2144,7 +2145,7 @@ mod tests {
                 suggested_boundaries: Some(suggested_boundaries),
                 cache: PxarLookaheadCache::new(None),
                 last_reusable_offset: None,
-                progress_stats: PxarArchiverProgressStats::default(),
+                progress_stats: Arc::new(PxarArchiverProgressStats::default()),
                 split_archive: true,
             };
 
diff --git a/pbs-client/src/pxar/mod.rs b/pbs-client/src/pxar/mod.rs
index b88fac33f..d6820d01a 100644
--- a/pbs-client/src/pxar/mod.rs
+++ b/pbs-client/src/pxar/mod.rs
@@ -58,7 +58,8 @@ mod flags;
 pub use flags::Flags;
 
 pub use create::{
-    MetadataArchiveReader, PxarCreateOptions, PxarPrevRef, PxarWriters, create_archive,
+    MetadataArchiveReader, PxarArchiverProgressStats, PxarCreateOptions, PxarPrevRef, PxarWriters,
+    create_archive,
 };
 pub use extract::{
     ErrorHandler, OverwriteFlags, PxarExtractContext, PxarExtractOptions, create_tar, create_zip,
diff --git a/pbs-client/src/pxar_backup_stream.rs b/pbs-client/src/pxar_backup_stream.rs
index 430eee01f..d1b46cf8a 100644
--- a/pbs-client/src/pxar_backup_stream.rs
+++ b/pbs-client/src/pxar_backup_stream.rs
@@ -20,6 +20,7 @@ use proxmox_log::debug;
 use pbs_datastore::catalog::{BackupCatalogWriter, CatalogWriter};
 
 use crate::inject_reused_chunks::InjectChunks;
+use crate::pxar::PxarArchiverProgressStats;
 use crate::pxar::create::PxarWriters;
 
 /// Stream implementation to encode and upload .pxar archives.
@@ -50,6 +51,7 @@ impl PxarBackupStream {
         options: crate::pxar::PxarCreateOptions,
         boundaries: Option<mpsc::Sender<InjectChunks>>,
         separate_payload_stream: bool,
+        archiver_progress_stats: Option<Arc<PxarArchiverProgressStats>>,
     ) -> Result<(Self, Option<Self>), Error> {
         let buffer_size = 256 * 1024;
 
@@ -102,6 +104,7 @@ impl PxarBackupStream {
                 options,
                 boundaries,
                 suggested_boundaries_tx,
+                archiver_progress_stats,
             )
             .await
             {
@@ -145,10 +148,18 @@ impl PxarBackupStream {
         options: crate::pxar::PxarCreateOptions,
         boundaries: Option<mpsc::Sender<InjectChunks>>,
         separate_payload_stream: bool,
+        archiver_progress_stats: Option<Arc<PxarArchiverProgressStats>>,
     ) -> Result<(Self, Option<Self>), Error> {
         let dir = nix::dir::Dir::open(dirname, OFlag::O_DIRECTORY, Mode::empty())?;
 
-        Self::new(dir, catalog, options, boundaries, separate_payload_stream)
+        Self::new(
+            dir,
+            catalog,
+            options,
+            boundaries,
+            separate_payload_stream,
+            archiver_progress_stats,
+        )
     }
 }
 
diff --git a/proxmox-backup-client/src/main.rs b/proxmox-backup-client/src/main.rs
index 5c52b7917..8ce5540d5 100644
--- a/proxmox-backup-client/src/main.rs
+++ b/proxmox-backup-client/src/main.rs
@@ -33,7 +33,9 @@ use pbs_api_types::{
     RateLimitConfig, ServerIdentity, SnapshotListItem, StorageStatus,
 };
 use pbs_client::catalog_shell::Shell;
-use pbs_client::pxar::{ErrorHandler as PxarErrorHandler, MetadataArchiveReader, PxarPrevRef};
+use pbs_client::pxar::{
+    ErrorHandler as PxarErrorHandler, MetadataArchiveReader, PxarArchiverProgressStats, PxarPrevRef,
+};
 use pbs_client::tools::{
     CHUNK_SIZE_SCHEMA, complete_archive_name, complete_auth_id, complete_backup_group,
     complete_backup_snapshot, complete_backup_source, complete_chunk_size,
@@ -50,8 +52,8 @@ use pbs_client::{
     BACKUP_SOURCE_SCHEMA, BackupDetectionMode, BackupReader, BackupRepository,
     BackupRepositoryArgs, BackupSpecificationType, BackupStats, BackupTargetArgs, BackupWriter,
     BackupWriterOptions, ChunkStream, FixedChunkStream, HttpClient, IndexType, InjectionData,
-    LogThrottle, PxarBackupStream, RemoteChunkReader, UploadOptions, delete_ticket_info,
-    parse_backup_specification, view_task_result,
+    LogThrottle, PxarBackupStream, RemoteChunkReader, UploadCounters, UploadOptions,
+    delete_ticket_info, parse_backup_specification, view_task_result,
 };
 use pbs_datastore::catalog::{BackupCatalogWriter, CatalogReader, CatalogWriter};
 use pbs_datastore::chunk_store::verify_chunk_size;
@@ -265,11 +267,13 @@ async fn backup_directory<P: AsRef<Path>>(
     catalog: Option<Arc<Mutex<Catalog>>>,
     pxar_create_options: pbs_client::pxar::PxarCreateOptions,
     upload_options: UploadOptions,
+    is_metadata_mode: bool,
 ) -> Result<(BackupStats, Option<BackupStats>), Error> {
     if let IndexType::Fixed(_) = upload_options.index_type {
         bail!("cannot backup directory with fixed chunk size!");
     }
 
+    let pxar_archiver_progress_stats = Arc::new(PxarArchiverProgressStats::default());
     let (payload_boundaries_tx, payload_boundaries_rx) = std::sync::mpsc::channel();
     let (pxar_stream, payload_stream) = PxarBackupStream::open(
         dir_path.as_ref(),
@@ -277,6 +281,7 @@ async fn backup_directory<P: AsRef<Path>>(
         pxar_create_options,
         Some(payload_boundaries_tx),
         payload_target.is_some(),
+        Some(pxar_archiver_progress_stats.clone()),
     )?;
 
     let mut chunk_stream = ChunkStream::new(pxar_stream, chunk_size, None, None);
@@ -293,7 +298,40 @@ async fn backup_directory<P: AsRef<Path>>(
 
     let stats = client.upload_stream(archive_name, stream, upload_options.clone(), None);
 
+    let progress_logger = move |counters: &UploadCounters, elapsed: &TimeSpan| {
+        let size = HumanByte::from(counters.total_stream_len());
+        let size_uploaded = HumanByte::from(counters.uploaded_len());
+
+        let total_files_processed = pxar_archiver_progress_stats.total_files_processed();
+        let total_reencoded_size = pxar_archiver_progress_stats.total_reencoded_size();
+
+        if is_metadata_mode {
+            let reuse_file_count = pxar_archiver_progress_stats.files_reused_count();
+            let reuse_payload_size = pxar_archiver_progress_stats.total_reused_payload_size();
+
+            let total_reuse_payload_size = HumanByte::from(reuse_payload_size);
+            let total_logical_file_size =
+                HumanByte::from(total_reencoded_size + reuse_payload_size);
+            log::info!(
+                "scanned {total_files_processed} files with {total_logical_file_size} \
+                       (reusing {reuse_file_count} files with {total_reuse_payload_size}) \
+                       of which processed {size} in {elapsed} and uploaded {size_uploaded}"
+            );
+        } else {
+            let total_logical_file_size = HumanByte::from(total_reencoded_size);
+            log::info!(
+                "scanned {total_files_processed} files with {total_logical_file_size} \
+                       of which processed {size} in {elapsed} and uploaded {size_uploaded}"
+            );
+        }
+    };
+
     if let Some(mut payload_stream) = payload_stream {
+        let upload_options = UploadOptions {
+            progress_logging_callback: Some(Arc::new(Box::new(progress_logger))),
+            ..upload_options
+        };
+
         let payload_target = payload_target
             .ok_or_else(|| format_err!("got payload stream, but no target archive name"))?;
 
@@ -1248,6 +1286,7 @@ async fn create_backup(
                     catalog.as_ref().cloned(),
                     pxar_options,
                     upload_options,
+                    detection_mode.is_metadata(),
                 )
                 .await?;
 
@@ -1268,6 +1307,12 @@ async fn create_backup(
             (BackupSpecificationType::IMAGE, false) => {
                 log_file("image", &filename, target.as_ref());
 
+                let progress_logger = |counters: &UploadCounters, elapsed: &TimeSpan| {
+                    let size = HumanByte::from(counters.total_stream_len());
+                    let size_uploaded = HumanByte::from(counters.uploaded_len());
+                    log::info!("processed {size} in {elapsed}, uploaded {size_uploaded}");
+                };
+
                 // 0 means fifo pipe with unknown size
                 let image_file_size = (size != 0).then_some(size);
                 let upload_options = UploadOptions {
@@ -1275,6 +1320,8 @@ async fn create_backup(
                     index_type: IndexType::Fixed(image_file_size),
                     compress: true,
                     encrypt: crypto.mode == CryptMode::Encrypt,
+                    progress_logging_callback: Some(Arc::new(Box::new(progress_logger))),
+                    ..UploadOptions::default()
                 };
 
                 let stats =
diff --git a/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs b/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
index ff21c9bee..b7f4fd141 100644
--- a/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
+++ b/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
@@ -375,6 +375,7 @@ fn extract(
                         options,
                         None,
                         None,
+                        None
                     )
                     .await
                 }
diff --git a/pxar-bin/src/main.rs b/pxar-bin/src/main.rs
index 4b14507ca..953c6e756 100644
--- a/pxar-bin/src/main.rs
+++ b/pxar-bin/src/main.rs
@@ -450,6 +450,7 @@ async fn create_archive(
         options,
         None,
         None,
+        None,
     )
     .await?;
 
diff --git a/tests/catar.rs b/tests/catar.rs
index aed23f866..81ca9d8db 100644
--- a/tests/catar.rs
+++ b/tests/catar.rs
@@ -41,6 +41,7 @@ fn run_test(dir_name: &str) -> Result<(), Error> {
         options,
         None,
         None,
+        None,
     ))?;
 
     Command::new("cmp")
-- 
2.47.3

[PATCH proxmox-backup 6/6] fix #7024: cli: add option to enable verbose logs

[Shan Shaji]

earlier, there was no option to enable verbose logging inside the CLI.
By default only info level logs were only logged.

To get more information, users had to enable debug logs by setting the
PBS_LOG environment variable, but that was too much information. To fix
this, accept a verbose option and log only necessary information in info
level when the flag is set as true.

Fixes: https://bugzilla.proxmox.com/show_bug.cgi?id=7024

Signed-off-by: Shan Shaji <s.shaji@proxmox.com>
---
 pbs-client/src/backup_writer.rs               |  9 +++---
 pbs-client/src/pxar/create.rs                 | 30 ++++++++++++++++---
 pbs-client/src/pxar/tools.rs                  |  9 +++++-
 proxmox-backup-client/src/main.rs             | 12 ++++++++
 .../src/proxmox_restore_daemon/api.rs         |  1 +
 pxar-bin/src/main.rs                          |  1 +
 6 files changed, 53 insertions(+), 9 deletions(-)

diff --git a/pbs-client/src/backup_writer.rs b/pbs-client/src/backup_writer.rs
index 8ae0cffe8..bf5a1a491 100644
--- a/pbs-client/src/backup_writer.rs
+++ b/pbs-client/src/backup_writer.rs
@@ -55,6 +55,7 @@ pub struct UploadOptions {
     pub encrypt: bool,
     pub index_type: IndexType,
     pub progress_logging_callback: Option<Arc<ProgressLoggerCallback>>,
+    pub verbose: bool,
 }
 
 /// Index type for upload options.
@@ -520,17 +521,17 @@ impl BackupWriter {
                 archive, reused, reused_percent
             );
         }
-        if enabled!(Level::DEBUG) && upload_stats.chunk_count > 0 {
-            debug!(
+        if options.verbose && upload_stats.chunk_count > 0 {
+            info!(
                 "{}: Reused {} from {} chunks.",
                 archive, upload_stats.chunk_reused, upload_stats.chunk_count
             );
-            debug!(
+            info!(
                 "{}: Average chunk size was {}.",
                 archive,
                 HumanByte::from(upload_stats.size / upload_stats.chunk_count)
             );
-            debug!(
+            info!(
                 "{}: Average time per request: {} microseconds.",
                 archive,
                 (upload_stats.duration.as_micros()) / (upload_stats.chunk_count as u128)
diff --git a/pbs-client/src/pxar/create.rs b/pbs-client/src/pxar/create.rs
index 7012a88dd..308bd20c0 100644
--- a/pbs-client/src/pxar/create.rs
+++ b/pbs-client/src/pxar/create.rs
@@ -39,7 +39,7 @@ use crate::inject_reused_chunks::InjectChunks;
 use crate::pxar::Flags;
 use crate::pxar::look_ahead_cache::{CacheEntry, CacheEntryData, PxarLookaheadCache};
 use crate::pxar::metadata::errno_is_unsupported;
-use crate::pxar::tools::assert_single_path_component;
+use crate::pxar::tools::{assert_single_path_component, log_message};
 
 const CHUNK_PADDING_THRESHOLD: f64 = 0.1;
 
@@ -60,6 +60,8 @@ pub struct PxarCreateOptions {
     pub previous_ref: Option<PxarPrevRef>,
     /// Maximum number of lookahead cache entries
     pub max_cache_size: Option<usize>,
+    /// Enable verbose logging
+    pub verbose: bool,
 }
 
 pub type MetadataArchiveReader = Arc<dyn ReadAt + Send + Sync + 'static>;
@@ -271,6 +273,7 @@ struct Archiver {
     last_reusable_offset: Option<u64>,
     progress_stats: Arc<PxarArchiverProgressStats>,
     split_archive: bool,
+    verbose: bool,
 }
 
 type Encoder<'a, T> = pxar::encoder::aio::Encoder<'a, T>;
@@ -383,6 +386,7 @@ where
         last_reusable_offset: None,
         progress_stats: archiver_progress_stats.unwrap_or_default(),
         split_archive,
+        verbose: options.verbose,
     };
 
     archiver
@@ -549,18 +553,35 @@ impl Archiver {
                         }
                         let range =
                             *offset..*offset + size + size_of::<pxar::format::Header>() as u64;
+
+                        if self.verbose {
+                            info!("reusable: {file_name:?}");
+                        }
+
                         debug!(
                             "reusable: {file_name:?} at range {range:?} has unchanged metadata."
                         );
                         return Ok(Some(range));
                     }
-                    debug!("re-encode: {file_name:?} not a regular file.");
+
+                    log_message(
+                        &format!("re-encode: {file_name:?} not a regular file."),
+                        self.verbose,
+                    );
                     return Ok(None);
                 }
-                debug!("re-encode: {file_name:?} metadata did not match.");
+
+                log_message(
+                    &format!("re-encode: {file_name:?} metadata did not match."),
+                    self.verbose,
+                );
                 return Ok(None);
             }
-            debug!("re-encode: {file_name:?} not found in previous archive.");
+
+            log_message(
+                &format!("re-encode: {file_name:?} not found in previous archive."),
+                self.verbose,
+            );
         }
 
         Ok(None)
@@ -2147,6 +2168,7 @@ mod tests {
                 last_reusable_offset: None,
                 progress_stats: Arc::new(PxarArchiverProgressStats::default()),
                 split_archive: true,
+                verbose: false,
             };
 
             let accessor = Accessor::new(pxar::PxarVariant::Unified(reader), metadata_size)
diff --git a/pbs-client/src/pxar/tools.rs b/pbs-client/src/pxar/tools.rs
index 0c8c2927e..3201ffd2d 100644
--- a/pbs-client/src/pxar/tools.rs
+++ b/pbs-client/src/pxar/tools.rs
@@ -9,6 +9,8 @@ use anyhow::{Context, Error, bail, format_err};
 use nix::sys::stat::Mode;
 
 use pathpatterns::MatchType;
+
+use proxmox_log::{debug, info};
 use pxar::accessor::ReadAt;
 use pxar::accessor::aio::{Accessor, Directory, FileEntry};
 use pxar::format::StatxTimestamp;
@@ -21,7 +23,6 @@ use pbs_datastore::BackupManifest;
 use pbs_datastore::dynamic_index::{BufferedDynamicReader, LocalDynamicReadAt};
 use pbs_datastore::index::IndexFile;
 use pbs_tools::crypt_config::CryptConfig;
-use proxmox_log::{debug, info};
 
 use crate::{BackupReader, RemoteChunkReader};
 
@@ -485,3 +486,9 @@ pub async fn pxar_metadata_catalog_find<'future, T: Clone + Send + Sync + ReadAt
     }
     Ok(())
 }
+
+pub(crate) fn log_message(msg: &str, verbose: bool) {
+    if verbose {
+        info!("{msg}");
+    }
+}
diff --git a/proxmox-backup-client/src/main.rs b/proxmox-backup-client/src/main.rs
index 8ce5540d5..368338699 100644
--- a/proxmox-backup-client/src/main.rs
+++ b/proxmox-backup-client/src/main.rs
@@ -18,6 +18,7 @@ use pathpatterns::{MatchEntry, MatchType, PatternFlag};
 use proxmox_async::blocking::TokioWriterAdapter;
 use proxmox_human_byte::HumanByte;
 use proxmox_io::StdChannelWriter;
+use proxmox_log::{Level, enabled};
 use proxmox_router::{ApiMethod, RpcEnvironment, cli::*};
 use proxmox_schema::api;
 use proxmox_sys::fs::{CreateOptions, file_get_json, image_size, replace_file};
@@ -828,6 +829,12 @@ fn spawn_catalog_upload(
                 optional: true,
                 default: false,
             },
+            "verbose": {
+                type: Boolean,
+                description: "Enable verbose logs.",
+                optional: true,
+                default: false,
+            }
         }
     }
  )]
@@ -871,6 +878,8 @@ async fn create_backup(
 
     let include_dev = param["include-dev"].as_array();
 
+    let verbose = param["verbose"].as_bool().unwrap_or_default() || enabled!(Level::DEBUG);
+
     let entries_max = param["entries-max"]
         .as_u64()
         .unwrap_or(pbs_client::pxar::ENCODER_MAX_ENTRIES as u64);
@@ -1268,12 +1277,14 @@ async fn create_backup(
                     skip_e2big_xattr,
                     previous_ref,
                     max_cache_size,
+                    verbose: verbose,
                 };
 
                 let upload_options = UploadOptions {
                     previous_manifest: previous_manifest.clone(),
                     compress: true,
                     encrypt: crypto.mode == CryptMode::Encrypt,
+                    verbose,
                     ..UploadOptions::default()
                 };
 
@@ -1321,6 +1332,7 @@ async fn create_backup(
                     compress: true,
                     encrypt: crypto.mode == CryptMode::Encrypt,
                     progress_logging_callback: Some(Arc::new(Box::new(progress_logger))),
+                    verbose,
                     ..UploadOptions::default()
                 };
 
diff --git a/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs b/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
index b7f4fd141..e890681fc 100644
--- a/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
+++ b/proxmox-restore-daemon/src/proxmox_restore_daemon/api.rs
@@ -364,6 +364,7 @@ fn extract(
                         skip_e2big_xattr: false,
                         previous_ref: None,
                         max_cache_size: None,
+                        verbose: false
                     };
 
                     let pxar_writer = pxar::PxarVariant::Unified(TokioWriter::new(writer));
diff --git a/pxar-bin/src/main.rs b/pxar-bin/src/main.rs
index 953c6e756..385f54a0d 100644
--- a/pxar-bin/src/main.rs
+++ b/pxar-bin/src/main.rs
@@ -383,6 +383,7 @@ async fn create_archive(
         skip_e2big_xattr: false,
         previous_ref: None,
         max_cache_size: None,
+        verbose: false,
     };
 
     let source = PathBuf::from(source);
-- 
2.47.3

Re: [PATCH proxmox-backup 5/6] fix #7024: cli: add more information inside the backup progress logs

[Thomas Ellmenreich]

I tested the backup client in both `img` as well as `pxar` mode and the output
works well. The only thing I noticed is that the progress logs during the
backup process are now specific to the image archive type. If I have
understood correctly this is because the callback is only created for the
image archive type.

Not sure if that was intentional, or I may have missed something, but if not,
it could be useful to note this in the commit message.

This could potentially also be something that is only active if
verbose logging is enabled.

As for the tests, I did the following, always using a older client, the new
client and the new client with `verbose` active.
- Image archive backup of a test node
- File archive backup of the node's /etc directory
- File archive backup of 25GB of random data
- Image archive backup of the same node with the additional 25GB
I still have all of the logs in case you want to take a look at them.

On Mon Jul 13, 2026 at 10:15 AM CEST, Shan Shaji wrote:
> previously, the progress logs only reported the processed stream size
> and uploaded size. To improve visibility additional information from
> `PxarArchiverProgressStats` and `UploadCounters` has been included in
> the logs.
>
> To access the upload statistics, a new callback field has been added to
> the UploadOptions struct that accepts UploadCounters and TimeSpan as
> parameters. Additionally, to include pxar metadata in the logs, the
> `PxarArchiverProgressStats` instance is now created earlier and shared
> between the archiver and the progress logger callback.

[snip]

> diff --git a/pbs-client/src/backup_writer.rs b/pbs-client/src/backup_writer.rs
> index 34d8db90b..8ae0cffe8 100644
> --- a/pbs-client/src/backup_writer.rs
> +++ b/pbs-client/src/backup_writer.rs
> @@ -874,20 +877,13 @@ impl BackupWriter {
>          let (upload_queue, upload_result) =
>              Self::append_chunk_queue(h2.clone(), wid, append_chunk_path, counters.clone());
>  
> -        let progress_handle = if archive.ends_with(".img.fidx")
> -            || archive.ends_with(".pxar.didx")
> -            || archive.ends_with(".ppxar.didx")
> -        {
> +        let progress_handle = if let Some(callback) = progress_logging_callback {
>              let counters = counters.clone();
>              Some(tokio::spawn(async move {
>                  loop {
>                      tokio::time::sleep(tokio::time::Duration::from_secs(60)).await;
> -
> -                    let size = HumanByte::from(counters.total_stream_len());
> -                    let size_uploaded = HumanByte::from(counters.uploaded_len());
>                      let elapsed = TimeSpan::from(start_time.elapsed());
> -
> -                    info!("processed {size} in {elapsed}, uploaded {size_uploaded}");

The removed logging that logged for all archive types

> +                    callback(&counters, &elapsed);
>                  }
>              }))
>          } else {

[snip]

> diff --git a/proxmox-backup-client/src/main.rs b/proxmox-backup-client/src/main.rs
> index 5c52b7917..8ce5540d5 100644
> --- a/proxmox-backup-client/src/main.rs
> +++ b/proxmox-backup-client/src/main.rs
> @@ -1268,6 +1307,12 @@ async fn create_backup(
>              (BackupSpecificationType::IMAGE, false) => {
>                  log_file("image", &filename, target.as_ref());
>  

Current callback (below) is only active for the Image type (as seen above).

> +                let progress_logger = |counters: &UploadCounters, elapsed: &TimeSpan| {
> +                    let size = HumanByte::from(counters.total_stream_len());
> +                    let size_uploaded = HumanByte::from(counters.uploaded_len());
> +                    log::info!("processed {size} in {elapsed}, uploaded {size_uploaded}");
> +                };
> +
>                  // 0 means fifo pipe with unknown size
>                  let image_file_size = (size != 0).then_some(size);
>                  let upload_options = UploadOptions {

[snip]