docker: log image pulls (#16849)

Log Docker image pulls, otherwise Pants will appear to hang if Pants decides it is necessary to pull an image.

[ci skip-build-wheels]

src/rust/engine/process_execution/src/docker.rs

@@ -8,9 +8,11 @@ use async_trait::async_trait;
 use bollard::container::{LogOutput, RemoveContainerOptions};
 use bollard::exec::StartExecResults;
 use bollard::image::CreateImageOptions;
+use bollard::service::CreateImageInfo;
 use bollard::{errors::Error as DockerError, Docker};
 use futures::stream::BoxStream;
 use futures::{StreamExt, TryFutureExt};
+use log::Level;
 use nails::execution::ExitCode;
 use parking_lot::Mutex;
 use store::Store;
@@ -162,36 +164,75 @@ async fn pull_image(docker: &Docker, image: &str, policy: ImagePullPolicy) -> Re
     }
   };
 
-  let do_pull = match (policy, image_exists) {
-    (ImagePullPolicy::Always, _) => true,
-    (ImagePullPolicy::IfMissing, false) => true,
-    (ImagePullPolicy::OnlyIfLatestOrMissing, false) => true,
-    (ImagePullPolicy::OnlyIfLatestOrMissing, true) if has_latest_tag => true,
+  let (do_pull, pull_reason) = match (policy, image_exists) {
+    (ImagePullPolicy::Always, _) => {
+      (true, "the image pull policy is set to \"always\"")
+    },
+    (ImagePullPolicy::IfMissing, false) => {
+      (true, "the image is missing locally")
+    },
+    (ImagePullPolicy::OnlyIfLatestOrMissing, false) => {
+      (true, "the image is missing locally")
+    },
+    (ImagePullPolicy::OnlyIfLatestOrMissing, true) if has_latest_tag => {
+      (true, "the image is present but the image tag is 'latest' and the image pull policy is set to pull images in this case")
+    },
     (ImagePullPolicy::Never, false) => {
       return Err(format!(
         "Image `{}` was not found locally and Pants is configured to not attempt to pull",
         image
       ));
     }
-    _ => false,
+    _ => (false, "")
   };
 
   if do_pull {
-    let create_image_options = CreateImageOptions::<String> {
-      from_image: image.to_string(),
-      ..CreateImageOptions::default()
-    };
+    in_workunit!(
+      "pull_docker_image",
+      Level::Info,
+      desc = Some(format!(
+        "Pulling Docker image `{image}` because {pull_reason}."
+      )),
+      |_workunit| async move {
+        let create_image_options = CreateImageOptions::<String> {
+          from_image: image.to_string(),
+          ..CreateImageOptions::default()
+        };
 
-    let mut result_stream = docker.create_image(Some(create_image_options), None, None);
-    while let Some(msg) = result_stream.next().await {
-      log::trace!("pull {}: {:?}", image, msg);
-      if let Err(err) = msg {
-        return Err(format!(
-          "Failed to pull Docker image `{}`: {:?}",
-          image, err
-        ));
+        let mut result_stream = docker.create_image(Some(create_image_options), None, None);
+        while let Some(msg) = result_stream.next().await {
+          log::trace!("pull {}: {:?}", image, msg);
+          match msg {
+            Ok(msg) => match msg {
+              CreateImageInfo {
+                error: Some(error), ..
+              } => {
+                let error_msg = format!("Failed to pull Docker image `{image}`: {error}");
+                log::error!("{error_msg}");
+                return Err(error_msg);
+              }
+              CreateImageInfo {
+                status: Some(status),
+                ..
+              } => {
+                log::debug!("Docker pull status: {status}");
+              }
+              // Ignore content in other event fields, namely `id`, `progress`, and `progress_detail`.
+              _ => (),
+            },
+            Err(err) => {
+              return Err(format!(
+                "Failed to pull Docker image `{}`: {:?}",
+                image, err
+              ))
+            }
+          }
+        }
+
+        Ok(())
       }
-    }
+    )
+    .await?;
   }
 
   Ok(())