feat: add official sync progress logging

infrastructure/src/bin/bat_official_sync.rs

@@ -1,12 +1,13 @@
 use bat_adapters::official::yostar_jp::PatchPlatform;
 use bat_infrastructure::{
-    OfficialServerInfoSource, OfficialUpdateConfig, OfficialUpdateService, OfficialUpdateStatus,
+    OfficialServerInfoSource, OfficialUpdateConfig, OfficialUpdateProgress, OfficialUpdateService,
+    OfficialUpdateStatus,
 };
 use serde::Serialize;
 use std::env;
 use std::path::PathBuf;
 use std::thread;
-use std::time::Duration;
+use std::time::{Duration, Instant};
 
 const EXIT_ERROR: i32 = 1;
 const EXIT_LOCKED: i32 = 75;
@@ -43,7 +44,10 @@ fn run() -> anyhow::Result<()> {
     if options.watch {
         run_watch(options)?;
     } else {
-        let report = OfficialUpdateService::new().run(&options.config)?;
+        let mut logger = ProgressLogger::new(options.progress);
+        let report = OfficialUpdateService::new().run_with_progress(&options.config, |event| {
+            logger.log(event);
+        })?;
         if should_print_status(report.update_status, options.quiet_up_to_date) {
             println!("{}", serde_json::to_string_pretty(&report)?);
         }
@@ -68,6 +72,7 @@ struct CliOptions {
     error_retry_interval: Duration,
     quiet_up_to_date: bool,
     quiet_up_to_date_explicit: bool,
+    progress: bool,
 }
 
 impl Default for CliOptions {
@@ -79,6 +84,7 @@ impl Default for CliOptions {
             error_retry_interval: Duration::from_secs(DEFAULT_ERROR_RETRY_SECONDS),
             quiet_up_to_date: false,
             quiet_up_to_date_explicit: false,
+            progress: true,
         }
     }
 }
@@ -96,16 +102,34 @@ fn run_watch(options: CliOptions) -> anyhow::Result<()> {
         ));
     }
     let service = OfficialUpdateService::new();
+    let mut logger = ProgressLogger::new(options.progress);
     loop {
         let mut sleep_for = options.interval;
-        match service.run(&options.config) {
+        logger.log_text("watch", "starting watch iteration");
+        match service.run_with_progress(&options.config, |event| logger.log(event)) {
             Ok(report) => {
                 if should_print_status(report.update_status, options.quiet_up_to_date) {
                     println!("{}", serde_json::to_string_pretty(&report)?);
                 }
+                logger.log_text(
+                    "watch",
+                    format!(
+                        "iteration finished with status={}; next check in {}",
+                        report.update_status.as_str(),
+                        format_duration(sleep_for)
+                    ),
+                );
             }
             Err(error) => {
                 sleep_for = options.error_retry_interval;
+                logger.log_text(
+                    "watch",
+                    format!(
+                        "iteration failed; retrying in {}: {}",
+                        format_duration(sleep_for),
+                        error
+                    ),
+                );
                 let payload = ErrorReport {
                     status: "error",
                     exit_code: EXIT_ERROR,
@@ -120,6 +144,37 @@ fn run_watch(options: CliOptions) -> anyhow::Result<()> {
     }
 }
 
+#[derive(Debug, Clone)]
+struct ProgressLogger {
+    enabled: bool,
+    started_at: Instant,
+}
+
+impl ProgressLogger {
+    fn new(enabled: bool) -> Self {
+        Self {
+            enabled,
+            started_at: Instant::now(),
+        }
+    }
+
+    fn log(&mut self, event: OfficialUpdateProgress) {
+        self.log_text(event.stage, event.message);
+    }
+
+    fn log_text(&mut self, stage: &str, message: impl AsRef<str>) {
+        if !self.enabled {
+            return;
+        }
+        eprintln!(
+            "[+{} INFO] [{}] {}",
+            format_duration(self.started_at.elapsed()),
+            stage,
+            message.as_ref()
+        );
+    }
+}
+
 fn should_print_status(status: OfficialUpdateStatus, quiet_up_to_date: bool) -> bool {
     !(quiet_up_to_date && status == OfficialUpdateStatus::UpToDate)
 }
@@ -233,6 +288,12 @@ fn parse_args_from(raw_args: impl IntoIterator<Item = String>) -> anyhow::Result
                 options.quiet_up_to_date = false;
                 options.quiet_up_to_date_explicit = true;
             }
+            "--progress" => {
+                options.progress = true;
+            }
+            "--no-progress" => {
+                options.progress = false;
+            }
             "--help" | "-h" => {
                 print_usage(&binary);
                 std::process::exit(0);
@@ -273,7 +334,7 @@ fn print_usage(binary: &str) {
          [--app-version 1.70.0] [--connection-group <name>] [--launcher-version 1.7.2] \
          [--platforms Windows,Android] [--output official_update_output] [--snapshot official-sync-snapshot.json] \
          [--curl curl] [--unzip unzip] [--dry-run] [--plan] [--force] [--audit-local|--no-audit-local] [--repair|--no-repair] \
-         [--watch] [--interval 1h|60m|3600s] [--error-retry 60s] [--quiet-up-to-date|--no-quiet-up-to-date]"
+         [--watch] [--interval 1h|60m|3600s] [--error-retry 60s] [--quiet-up-to-date|--no-quiet-up-to-date] [--progress|--no-progress]"
     );
 }
 
@@ -304,6 +365,14 @@ fn parse_duration(value: &str) -> anyhow::Result<Duration> {
     Ok(Duration::from_secs(amount.saturating_mul(multiplier)))
 }
 
+fn format_duration(duration: Duration) -> String {
+    let total_millis = duration.as_millis();
+    let minutes = total_millis / 60_000;
+    let seconds = (total_millis / 1_000) % 60;
+    let millis = total_millis % 1_000;
+    format!("{minutes:02}:{seconds:02}.{millis:03}")
+}
+
 fn parse_platforms(value: &str) -> Result<Vec<PatchPlatform>, String> {
     value
         .split(',')
@@ -368,6 +437,7 @@ mod tests {
         );
         assert!(!options.quiet_up_to_date);
         assert!(!options.quiet_up_to_date_explicit);
+        assert!(options.progress);
     }
 
     #[test]
@@ -446,6 +516,18 @@ mod tests {
         assert_eq!(options.error_retry_interval, Duration::from_secs(30));
     }
 
+    #[test]
+    fn parses_progress_flags() {
+        let options = parse(&["bat-official-sync"]).unwrap();
+        assert!(options.progress);
+
+        let options = parse(&["bat-official-sync", "--no-progress"]).unwrap();
+        assert!(!options.progress);
+
+        let options = parse(&["bat-official-sync", "--no-progress", "--progress"]).unwrap();
+        assert!(options.progress);
+    }
+
     #[test]
     fn explicit_no_quiet_up_to_date_overrides_watch_default() {
         let options = parse(&[
@@ -485,6 +567,12 @@ mod tests {
         assert_eq!(parse_duration("3600").unwrap(), Duration::from_secs(3600));
     }
 
+    #[test]
+    fn formats_progress_durations() {
+        assert_eq!(format_duration(Duration::from_millis(7)), "00:00.007");
+        assert_eq!(format_duration(Duration::from_millis(65_432)), "01:05.432");
+    }
+
     #[test]
     fn quiet_up_to_date_suppresses_only_clean_reports() {
         assert!(!should_print_status(OfficialUpdateStatus::UpToDate, true));