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 <[email protected]>

Author: cgwalters

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<_> {

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
 }