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 50A11982D5 for ; Thu, 13 Apr 2023 17:42:07 +0200 (CEST) Received: from firstgate.proxmox.com (localhost [127.0.0.1]) by firstgate.proxmox.com (Proxmox) with ESMTP id 2FA9A1D6B6 for ; Thu, 13 Apr 2023 17:42:07 +0200 (CEST) Received: from lana.proxmox.com (unknown [94.136.29.99]) by firstgate.proxmox.com (Proxmox) with ESMTP for ; Thu, 13 Apr 2023 17:42:05 +0200 (CEST) Received: by lana.proxmox.com (Postfix, from userid 10043) id 3F06E2C27E1; Thu, 13 Apr 2023 17:42:05 +0200 (CEST) From: Stefan Hanreich To: pbs-devel@lists.proxmox.com Date: Thu, 13 Apr 2023 17:41:56 +0200 Message-Id: <20230413154156.2304040-4-s.hanreich@proxmox.com> X-Mailer: git-send-email 2.30.2 In-Reply-To: <20230413154156.2304040-1-s.hanreich@proxmox.com> References: <20230413154156.2304040-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.448 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 Subject: [pbs-devel] [PATCH proxmox-backup v3 3/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: Thu, 13 Apr 2023 15:42:07 -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. Printing the different reasons for skipping snapshots makes it easier to check whether the transfer-last parameter is working as expected. Suggested-By: Fabian Grünbichler Signed-off-by: Stefan Hanreich --- Still quite unsure about the format of the skip reasons, I've opted for newlines since putting everything on one line seemed quite long: 2023-04-13T15:30:12+02:00: skipped: 4 snapshot(s) (2023-04-12T14:55:59Z .. 2023-04-13T13:02:09Z), 2 already synced, 2 due to transfer-last One upside of this would be, that it is easy to grep. The current version with newlines looks like this: 2023-04-13T15:08:31+02:00: skipped: 9 snapshot(s) (2023-04-12T14:55:59Z .. 2023-04-13T13:02:22Z) 7 older than newest local snapshot 2 due to transfer-last Those would be the only lines in the Web UI Task Log without prepended timestamps, which might be suboptimal as well. I could move the output of the skip reasons out of the fmt method to be more flexible, but having everything contained there seemed desirable to me - so I settled on this solution for now. Complete sample output for the sync of a group in the Web UI after this commit: 2023-04-13T15:08:31+02:00: sync group vm/101 2023-04-13T15:08:31+02:00: re-sync snapshot vm/101/2023-04-13T13:02:17Z 2023-04-13T15:08:31+02:00: no data changes 2023-04-13T15:08:31+02:00: percentage done: 28.79% (1/6 groups, 8/11 snapshots in group #2) 2023-04-13T15:08:31+02:00: sync snapshot vm/101/2023-04-13T13:02:25Z 2023-04-13T15:08:31+02:00: sync archive qemu-server.conf.blob 2023-04-13T15:08:31+02:00: sync archive drive-virtio0.img.fidx 2023-04-13T15:08:31+02:00: downloaded 0 bytes (0.00 MiB/s) 2023-04-13T15:08:31+02:00: sync archive drive-scsi0.img.fidx 2023-04-13T15:08:31+02:00: downloaded 0 bytes (0.00 MiB/s) 2023-04-13T15:08:31+02:00: got backup log file "client.log.blob" 2023-04-13T15:08:31+02:00: sync snapshot vm/101/2023-04-13T13:02:25Z done 2023-04-13T15:08:31+02:00: percentage done: 33.33% (2/6 groups) 2023-04-13T15:08:31+02:00: skipped: 9 snapshot(s) (2023-04-12T14:55:59Z .. 2023-04-13T13:02:22Z) 7 older than newest local snapshot 2 due to transfer-last Any input would be appreciated, as I'm a bit torn. src/server/pull.rs | 32 +++++++++++++++++++++++++++----- 1 file changed, 27 insertions(+), 5 deletions(-) diff --git a/src/server/pull.rs b/src/server/pull.rs index 37058f9b..d6e3c2c4 100644 --- a/src/server/pull.rs +++ b/src/server/pull.rs @@ -1,6 +1,7 @@ //! Sync datastore from remote server use std::collections::{HashMap, HashSet}; +use std::fmt::Write; use std::io::{Seek, SeekFrom}; use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::{Arc, Mutex}; @@ -535,7 +536,6 @@ 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(()) @@ -589,12 +589,32 @@ impl SkipInfo { impl std::fmt::Display for SkipInfo { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - write!( - f, - "skipped: {} snapshot(s) ({}) older than the newest local snapshot", + let mut reason_string = String::new(); + + writeln!( + reason_string, + "skipped: {} snapshot(s) ({}), ", self.count(), self.affected().map_err(|_| std::fmt::Error)? - ) + )?; + + if self.already_synced_count > 0 { + writeln!( + reason_string, + "{} already synced", + self.already_synced_count + )?; + } + + if self.transfer_last_count > 0 { + writeln!( + reason_string, + "{} due to transfer-last", + self.transfer_last_count + )?; + } + + write!(f, "{}", reason_string.trim_end()) } } @@ -635,6 +655,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() -- 2.30.2