From adc37abfaac47dad094b2b902e904adda0d42946 Mon Sep 17 00:00:00 2001
From: Colin Walters <walters@verbum.org>
Date: Sun, 27 Oct 2024 15:41:48 -0400
Subject: [PATCH] utils: Print and log time for async_task_with_spinner

Things we do via this mechanism can take some time; let's
log the elapsed time for greater visibility both to the
human output *and* log to the journal.

Signed-off-by: Colin Walters <walters@verbum.org>
---
 lib/src/deploy.rs |  1 +
 lib/src/utils.rs  | 12 ++++++++++--
 2 files changed, 11 insertions(+), 2 deletions(-)

diff --git a/lib/src/deploy.rs b/lib/src/deploy.rs
index 8e9183c6..68fc4d5a 100644
--- a/lib/src/deploy.rs
+++ b/lib/src/deploy.rs
@@ -394,6 +394,7 @@ async fn deploy(
     let ostree_commit = image.ostree_commit.to_string();
     // GKeyFile also isn't Send! So we serialize that as a string...
     let origin_data = origin.to_data();
+    tracing::debug!("Deploying commit {ostree_commit}");
     let r = async_task_with_spinner(
         "Deploying",
         spawn_blocking_cancellable_flatten(move |cancellable| -> Result<_> {
diff --git a/lib/src/utils.rs b/lib/src/utils.rs
index 81b253fe..33403afe 100644
--- a/lib/src/utils.rs
+++ b/lib/src/utils.rs
@@ -6,6 +6,8 @@ use std::time::Duration;
 
 use anyhow::{Context, Result};
 use cap_std_ext::cap_std::fs::Dir;
+use indicatif::HumanDuration;
+use libsystemd::logging::journal_print;
 use ostree::glib;
 use ostree_ext::container::SignatureSource;
 use ostree_ext::ostree;
@@ -119,6 +121,7 @@ pub(crate) async fn async_task_with_spinner<F, T>(msg: &str, f: F) -> T
 where
     F: Future<Output = T>,
 {
+    let start_time = std::time::Instant::now();
     let pb = indicatif::ProgressBar::new_spinner();
     let style = indicatif::ProgressStyle::default_bar();
     pb.set_style(style.template("{spinner} {msg}").unwrap());
@@ -131,10 +134,15 @@ where
         std::io::stdout().flush().unwrap();
     }
     let r = f.await;
+    let elapsed = HumanDuration(start_time.elapsed());
+    let _ = journal_print(
+        libsystemd::logging::Priority::Info,
+        &format!("completed task in {elapsed}: {msg}"),
+    );
     if pb.is_hidden() {
-        println!("done");
+        println!("done ({elapsed})");
     } else {
-        pb.finish_with_message(format!("{msg}: done"));
+        pb.finish_with_message(format!("{msg}: done ({elapsed})"));
     }
     r
 }