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 4E36098D3A for ; Tue, 18 Apr 2023 16:59:50 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 2A57E19283 for ; Tue, 18 Apr 2023 16:59:50 +0200 (CEST) Received: from lana.proxmox.com (unknown [94.136.29.99]) by firstgate.proxmox.com (Proxmox) with ESMTP for ; Tue, 18 Apr 2023 16:59:49 +0200 (CEST) Received: by lana.proxmox.com (Postfix, from userid 10043) id DAFE22C13C5; Tue, 18 Apr 2023 16:59:48 +0200 (CEST) From: Stefan Hanreich To: pbs-devel@lists.proxmox.com Date: Tue, 18 Apr 2023 16:59:46 +0200 Message-Id: <20230418145947.3003473-3-s.hanreich@proxmox.com> X-Mailer: git-send-email 2.30.2 In-Reply-To: <20230418145947.3003473-1-s.hanreich@proxmox.com> References: <20230418145947.3003473-1-s.hanreich@proxmox.com> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-SPAM-LEVEL: Spam detection results: 0 AWL -0.427 Adjusted score from AWL reputation of From: address BAYES_00 -1.9 Bayes spam probability is 0 to 1% DMARC_MISSING 0.1 Missing DMARC policy KAM_DMARC_STATUS 0.01 Test Rule for DKIM or SPF Failure with Strict Alignment KAM_LAZY_DOMAIN_SECURITY 1 Sending domain does not have any anti-forgery methods RDNS_NONE 0.793 Delivered to internal network by a host with no rDNS SPF_HELO_NONE 0.001 SPF: HELO does not publish an SPF Record SPF_NONE 0.001 SPF: sender does not publish an SPF Record T_SCC_BODY_TEXT_LINE -0.01 - Subject: [pbs-devel] [PATCH v4 proxmox-backup 2/3] sync job: pull: improve log output 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: Tue, 18 Apr 2023 14:59:50 -0000 Adding an opening line for every group makes parsing the log easier. We can also remove the 're-sync [...] done' line, because the next line should be a progress line anyway. The new output for the sync job/pull logs looks as follows: - skipped already synced (happens in most jobs, except for first run) - re-sync of last synced snapshot (if it still exists on source) - skipped because of transfer-last (if set and skips something) - sync of new snapshots (if they exist) Suggested-By: Fabian Grünbichler Signed-off-by: Stefan Hanreich --- src/server/pull.rs | 54 +++++++++++++++++++++++++++++++++++----------- 1 file changed, 41 insertions(+), 13 deletions(-) diff --git a/src/server/pull.rs b/src/server/pull.rs index 0219d47e..e50037ed 100644 --- a/src/server/pull.rs +++ b/src/server/pull.rs @@ -535,19 +535,39 @@ async fn pull_snapshot_from( } else { task_log!(worker, "re-sync snapshot {}", snapshot.dir()); pull_snapshot(worker, reader, snapshot, downloaded_chunks).await?; - task_log!(worker, "re-sync snapshot {} done", snapshot.dir()); } Ok(()) } +enum SkipReason { + AlreadySynced, + TransferLast, +} + struct SkipInfo { oldest: i64, newest: i64, count: u64, + skip_reason: SkipReason, } impl SkipInfo { + fn new(skip_reason: SkipReason) -> Self { + SkipInfo { + oldest: i64::MAX, + newest: i64::MIN, + count: 0, + skip_reason, + } + } + + fn reset(&mut self) { + self.count = 0; + self.oldest = i64::MAX; + self.newest = i64::MIN; + } + fn update(&mut self, backup_time: i64) { self.count += 1; @@ -575,11 +595,17 @@ impl SkipInfo { impl std::fmt::Display for SkipInfo { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let reason_string = match self.skip_reason { + SkipReason::AlreadySynced => "older than the newest local snapshot", + SkipReason::TransferLast => "due to transfer-last", + }; + write!( f, - "skipped: {} snapshot(s) ({}) older than the newest local snapshot", + "skipped: {} snapshot(s) ({}) - {}", self.count, - self.affected().map_err(|_| std::fmt::Error)? + self.affected().map_err(|_| std::fmt::Error)?, + reason_string ) } } @@ -610,6 +636,8 @@ async fn pull_group( remote_ns: BackupNamespace, progress: &mut StoreProgress, ) -> Result<(), Error> { + task_log!(worker, "sync group {}", group); + let path = format!( "api2/json/admin/datastore/{}/snapshots", params.source.store() @@ -645,11 +673,8 @@ async fn pull_group( progress.group_snapshots = list.len() as u64; - let mut skip_info = SkipInfo { - oldest: i64::MAX, - newest: i64::MIN, - count: 0, - }; + let mut already_synced_skip_info = SkipInfo::new(SkipReason::AlreadySynced); + let mut transfer_last_skip_info = SkipInfo::new(SkipReason::TransferLast); let total_amount = list.len(); @@ -674,12 +699,19 @@ async fn pull_group( remote_snapshots.insert(snapshot.time); if last_sync_time > snapshot.time { - skip_info.update(snapshot.time); + already_synced_skip_info.update(snapshot.time); continue; + } else if already_synced_skip_info.count > 0 { + task_log!(worker, "{}", already_synced_skip_info); + already_synced_skip_info.reset(); } if pos < cutoff && last_sync_time != snapshot.time { + transfer_last_skip_info.update(snapshot.time); continue; + } else if transfer_last_skip_info.count > 0 { + task_log!(worker, "{}", transfer_last_skip_info); + transfer_last_skip_info.reset(); } // get updated auth_info (new tickets) @@ -739,10 +771,6 @@ async fn pull_group( } } - if skip_info.count > 0 { - task_log!(worker, "{}", skip_info); - } - Ok(()) } -- 2.30.2