Add systemd structured logging for bootc state changes

Author: gursewak1997

Cargo.lock

@@ -65,6 +65,7 @@ tokio-util = { features = ["io-util"], version = "0.7.10" }
 toml = "0.9.5"
 tracing = "0.1.40"
 tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
+tracing-journald = "0.3.1"
 uzers = "0.12"
 xshell = "0.2.6"
 

Cargo.toml

@@ -39,7 +39,23 @@ pub(crate) struct ResolvedBoundImage {
 
 /// Given a deployment, pull all container images it references.
 pub(crate) async fn pull_bound_images(sysroot: &Storage, deployment: &Deployment) -> Result<()> {
-    let bound_images = query_bound_images_for_deployment(sysroot.get_ostree()?, deployment)?;
+    // Log the bound images operation to systemd journal
+    const BOUND_IMAGES_JOURNAL_ID: &str = "1a0b9c8d7e6f5a4b3c2d1e0f9a8b7c6d5";
+    tracing::info!(
+        message_id = BOUND_IMAGES_JOURNAL_ID,
+        bootc.deployment.osname = deployment.osname().as_str(),
+        bootc.deployment.checksum = deployment.csum().as_str(),
+        "Starting pull of bound images for deployment"
+    );
+
+    let ostree = sysroot.get_ostree()?;
+    let bound_images = query_bound_images_for_deployment(ostree, deployment)?;
+    tracing::info!(
+        message_id = BOUND_IMAGES_JOURNAL_ID,
+        bootc.bound_images_count = bound_images.len(),
+        "Found {} bound images to pull",
+        bound_images.len()
+    );
     pull_images(sysroot, bound_images).await
 }
 

crates/lib/src/boundimage.rs

@@ -1067,6 +1067,26 @@ async fn switch(opts: SwitchOpts) -> Result<()> {
         println!("Image specification is unchanged.");
         return Ok(());
     }
+
+    // Log the switch operation to systemd journal
+    const SWITCH_JOURNAL_ID: &str = "7a6b5c4d3e2f1a0b9c8d7e6f5a4b3c2d1";
+    let old_image = host
+        .spec
+        .image
+        .as_ref()
+        .map(|i| i.image.as_str())
+        .unwrap_or("none");
+
+    tracing::info!(
+        message_id = SWITCH_JOURNAL_ID,
+        bootc.old_image_reference = old_image,
+        bootc.new_image_reference = &target.image,
+        bootc.new_image_transport = &target.transport,
+        "Switching from image {} to {}",
+        old_image,
+        target.image
+    );
+
     let new_spec = RequiredHostSpec::from_spec(&new_spec)?;
 
     let fetched = crate::deploy::pull(repo, &target, None, opts.quiet, prog.clone()).await?;

crates/lib/src/cli.rs

@@ -429,11 +429,24 @@ pub(crate) async fn pull_from_prepared(
     let imgref_canonicalized = imgref.clone().canonicalize()?;
     tracing::debug!("Canonicalized image reference: {imgref_canonicalized:#}");
 
+    // Log successful import completion
+    const IMPORT_COMPLETE_JOURNAL_ID: &str = "4d3e2f1a0b9c8d7e6f5a4b3c2d1e0f9a8";
+
+    tracing::info!(
+        message_id = IMPORT_COMPLETE_JOURNAL_ID,
+        bootc.image.reference = &imgref.image,
+        bootc.image.transport = &imgref.transport,
+        bootc.manifest_digest = import.manifest_digest.as_ref(),
+        bootc.ostree_commit = &import.merge_commit,
+        "Successfully imported image: {}",
+        imgref
+    );
+
     if let Some(msg) =
         ostree_container::store::image_filtered_content_warning(&import.filtered_files)
             .context("Image content warning")?
     {
-        crate::journal::journal_print(libsystemd::logging::Priority::Notice, &msg);
+        tracing::info!("{}", msg);
     }
     Ok(Box::new((*import).into()))
 }
@@ -447,8 +460,30 @@ pub(crate) async fn pull(
     prog: ProgressWriter,
 ) -> Result<Box<ImageState>> {
     match prepare_for_pull(repo, imgref, target_imgref).await? {
-        PreparedPullResult::AlreadyPresent(existing) => Ok(existing),
+        PreparedPullResult::AlreadyPresent(existing) => {
+            // Log that the image was already present (Debug level since it's not actionable)
+            const IMAGE_ALREADY_PRESENT_ID: &str = "5c4d3e2f1a0b9c8d7e6f5a4b3c2d1e0f9";
+            tracing::debug!(
+                message_id = IMAGE_ALREADY_PRESENT_ID,
+                bootc.image.reference = &imgref.image,
+                bootc.image.transport = &imgref.transport,
+                bootc.status = "already_present",
+                "Image already present: {}",
+                imgref
+            );
+            Ok(existing)
+        }
         PreparedPullResult::Ready(prepared_image_meta) => {
+            // Log that we're pulling a new image
+            const PULLING_NEW_IMAGE_ID: &str = "6d5e4f3a2b1c0d9e8f7a6b5c4d3e2f1a0";
+            tracing::info!(
+                message_id = PULLING_NEW_IMAGE_ID,
+                bootc.image.reference = &imgref.image,
+                bootc.image.transport = &imgref.transport,
+                bootc.status = "pulling_new",
+                "Pulling new image: {}",
+                imgref
+            );
             Ok(pull_from_prepared(imgref, quiet, prog, *prepared_image_meta).await?)
         }
     }
@@ -466,6 +501,14 @@ pub(crate) async fn wipe_ostree(sysroot: Sysroot) -> Result<()> {
 }
 
 pub(crate) async fn cleanup(sysroot: &Storage) -> Result<()> {
+    // Log the cleanup operation to systemd journal
+    const CLEANUP_JOURNAL_ID: &str = "2f1a0b9c8d7e6f5a4b3c2d1e0f9a8b7c6";
+
+    tracing::info!(
+        message_id = CLEANUP_JOURNAL_ID,
+        "Starting cleanup of old images and deployments"
+    );
+
     let bound_prune = prune_container_store(sysroot);
 
     // We create clones (just atomic reference bumps) here to move to the thread.
@@ -615,6 +658,20 @@ pub(crate) async fn stage(
     spec: &RequiredHostSpec<'_>,
     prog: ProgressWriter,
 ) -> Result<()> {
+    // Log the staging operation to systemd journal with comprehensive upgrade information
+    const STAGE_JOURNAL_ID: &str = "8f7a2b1c3d4e5f6a7b8c9d0e1f2a3b4c";
+
+    tracing::info!(
+        message_id = STAGE_JOURNAL_ID,
+        bootc.image.reference = &spec.image.image,
+        bootc.image.transport = &spec.image.transport,
+        bootc.manifest_digest = image.manifest_digest.as_ref(),
+        bootc.stateroot = stateroot,
+        "Staging image for deployment: {} (digest: {})",
+        spec.image,
+        image.manifest_digest
+    );
+
     let ostree = sysroot.get_ostree()?;
     let mut subtask = SubTaskStep {
         subtask: "merging".into(),
@@ -773,19 +830,26 @@ pub(crate) async fn rollback(sysroot: &Storage) -> Result<()> {
     let rollback_image = rollback_status
         .query_image(repo)?
         .ok_or_else(|| anyhow!("Rollback is not container image based"))?;
-    let msg = format!("Rolling back to image: {}", rollback_image.manifest_digest);
-    libsystemd::logging::journal_send(
-        libsystemd::logging::Priority::Info,
-        &msg,
-        [
-            ("MESSAGE_ID", ROLLBACK_JOURNAL_ID),
-            (
-                "BOOTC_MANIFEST_DIGEST",
-                rollback_image.manifest_digest.as_ref(),
-            ),
-        ]
-        .into_iter(),
-    )?;
+
+    // Get current booted image for comparison
+    let current_image = host
+        .status
+        .booted
+        .as_ref()
+        .and_then(|b| b.query_image(repo).ok()?);
+
+    tracing::info!(
+        message_id = ROLLBACK_JOURNAL_ID,
+        bootc.manifest_digest = rollback_image.manifest_digest.as_ref(),
+        bootc.ostree_commit = &rollback_image.merge_commit,
+        bootc.rollback_type = if reverting { "revert" } else { "rollback" },
+        bootc.current_manifest_digest = current_image
+            .as_ref()
+            .map(|i| i.manifest_digest.as_ref())
+            .unwrap_or("none"),
+        "Rolling back to image: {}",
+        rollback_image.manifest_digest
+    );
     // SAFETY: If there's a rollback status, then there's a deployment
     let rollback_deployment = deployments.rollback.expect("rollback deployment");
     let new_deployments = if reverting {
@@ -833,6 +897,18 @@ fn find_newest_deployment_name(deploysdir: &Dir) -> Result<String> {
 
 // Implementation of `bootc switch --in-place`
 pub(crate) fn switch_origin_inplace(root: &Dir, imgref: &ImageReference) -> Result<String> {
+    // Log the in-place switch operation to systemd journal
+    const SWITCH_INPLACE_JOURNAL_ID: &str = "3e2f1a0b9c8d7e6f5a4b3c2d1e0f9a8b7";
+
+    tracing::info!(
+        message_id = SWITCH_INPLACE_JOURNAL_ID,
+        bootc.image.reference = &imgref.image,
+        bootc.image.transport = &imgref.transport,
+        bootc.switch_type = "in_place",
+        "Performing in-place switch to image: {}",
+        imgref
+    );
+
     // First, just create the new origin file
     let origin = origin_from_imageref(imgref)?;
     let serialized_origin = origin.to_data();

crates/lib/src/deploy.rs

@@ -1476,6 +1476,26 @@ fn installation_complete() {
 #[context("Installing to disk")]
 #[cfg(feature = "install-to-disk")]
 pub(crate) async fn install_to_disk(mut opts: InstallToDiskOpts) -> Result<()> {
+    // Log the disk installation operation to systemd journal
+    const INSTALL_DISK_JOURNAL_ID: &str = "8b7c6d5e4f3a2b1c0d9e8f7a6b5c4d3e2";
+    let source_image = opts
+        .source_opts
+        .source_imgref
+        .as_ref()
+        .map(|s| s.as_str())
+        .unwrap_or("none");
+    let target_device = opts.block_opts.device.as_str();
+
+    tracing::info!(
+        message_id = INSTALL_DISK_JOURNAL_ID,
+        bootc.source_image = source_image,
+        bootc.target_device = target_device,
+        bootc.via_loopback = if opts.via_loopback { "true" } else { "false" },
+        "Starting disk installation from {} to {}",
+        source_image,
+        target_device
+    );
+
     let mut block_opts = opts.block_opts;
     let target_blockdev_meta = block_opts
         .device
@@ -1701,6 +1721,26 @@ pub(crate) async fn install_to_filesystem(
     targeting_host_root: bool,
     cleanup: Cleanup,
 ) -> Result<()> {
+    // Log the installation operation to systemd journal
+    const INSTALL_FILESYSTEM_JOURNAL_ID: &str = "9a8b7c6d5e4f3a2b1c0d9e8f7a6b5c4d3";
+    let source_image = opts
+        .source_opts
+        .source_imgref
+        .as_ref()
+        .map(|s| s.as_str())
+        .unwrap_or("none");
+    let target_path = opts.filesystem_opts.root_path.as_str();
+
+    tracing::info!(
+        message_id = INSTALL_FILESYSTEM_JOURNAL_ID,
+        bootc.source_image = source_image,
+        bootc.target_path = target_path,
+        bootc.targeting_host_root = if targeting_host_root { "true" } else { "false" },
+        "Starting filesystem installation from {} to {}",
+        source_image,
+        target_path
+    );
+
     // Gather global state, destructuring the provided options.
     // IMPORTANT: We might re-execute the current process in this function (for SELinux among other things)
     // IMPORTANT: and hence anything that is done before MUST BE IDEMPOTENT.
@@ -1933,6 +1973,30 @@ pub(crate) async fn install_to_filesystem(
 }
 
 pub(crate) async fn install_to_existing_root(opts: InstallToExistingRootOpts) -> Result<()> {
+    // Log the existing root installation operation to systemd journal
+    const INSTALL_EXISTING_ROOT_JOURNAL_ID: &str = "7c6d5e4f3a2b1c0d9e8f7a6b5c4d3e2f1";
+    let source_image = opts
+        .source_opts
+        .source_imgref
+        .as_ref()
+        .map(|s| s.as_str())
+        .unwrap_or("none");
+    let target_path = opts.root_path.as_str();
+
+    tracing::info!(
+        message_id = INSTALL_EXISTING_ROOT_JOURNAL_ID,
+        bootc.source_image = source_image,
+        bootc.target_path = target_path,
+        bootc.cleanup = if opts.cleanup {
+            "trigger_on_next_boot"
+        } else {
+            "skip"
+        },
+        "Starting installation to existing root from {} to {}",
+        source_image,
+        target_path
+    );
+
     let cleanup = match opts.cleanup {
         true => Cleanup::TriggerOnNextBoot,
         false => Cleanup::Skip,
@@ -1957,14 +2021,33 @@ pub(crate) async fn install_to_existing_root(opts: InstallToExistingRootOpts) ->
 
 /// Implementation of `bootc install finalize`.
 pub(crate) async fn install_finalize(target: &Utf8Path) -> Result<()> {
+    // Log the installation finalization operation to systemd journal
+    const INSTALL_FINALIZE_JOURNAL_ID: &str = "6d5e4f3a2b1c0d9e8f7a6b5c4d3e2f1a0";
+
+    tracing::info!(
+        message_id = INSTALL_FINALIZE_JOURNAL_ID,
+        bootc.target_path = target.as_str(),
+        "Starting installation finalization for target: {}",
+        target
+    );
+
     crate::cli::require_root(false)?;
     let sysroot = ostree::Sysroot::new(Some(&gio::File::for_path(target)));
     sysroot.load(gio::Cancellable::NONE)?;
-    let deployments = sysroot.deployments();
-    // Verify we find a deployment
-    if deployments.is_empty() {
-        anyhow::bail!("Failed to find deployment in {target}");
-    }
+
+    let deployment = sysroot
+        .deployments()
+        .into_iter()
+        .next()
+        .ok_or_else(|| anyhow!("Failed to find deployment in {target}"))?;
+
+    // Log successful finalization
+    tracing::info!(
+        message_id = INSTALL_FINALIZE_JOURNAL_ID,
+        bootc.target_path = target.as_str(),
+        "Successfully finalized installation for target: {}",
+        target
+    );
 
     // For now that's it! We expect to add more validation/postprocessing
     // later, such as munging `etc/fstab` if needed. See

crates/lib/src/install.rs

@@ -276,9 +276,17 @@ pub(crate) async fn impl_completion(
     sysroot: &ostree::Sysroot,
     stateroot: Option<&str>,
 ) -> Result<()> {
+    // Log the completion operation to systemd journal
+    const COMPLETION_JOURNAL_ID: &str = "0f9a8b7c6d5e4f3a2b1c0d9e8f7a6b5c4";
+    tracing::info!(
+        message_id = COMPLETION_JOURNAL_ID,
+        bootc.stateroot = stateroot.unwrap_or("default"),
+        "Starting bootc installation completion"
+    );
+
     let deployment = &sysroot
         .merge_deployment(stateroot)
-        .ok_or_else(|| anyhow::anyhow!("Failed to find deployment (stateroot={stateroot:?}"))?;
+        .ok_or_else(|| anyhow::anyhow!("Failed to find deployment (stateroot={stateroot:?})"))?;
     let sysroot_dir = crate::utils::sysroot_dir(&sysroot)?;
 
     // Create a subdir in /run
@@ -291,7 +299,16 @@ pub(crate) async fn impl_completion(
 
     // ostree-ext doesn't do logically bound images
     let bound_images = crate::boundimage::query_bound_images_for_deployment(sysroot, deployment)?;
+
     if !bound_images.is_empty() {
+        // Log bound images found
+        tracing::info!(
+            message_id = COMPLETION_JOURNAL_ID,
+            bootc.bound_images_count = bound_images.len(),
+            "Found {} bound images for completion",
+            bound_images.len()
+        );
+
         // load the selinux policy from the target ostree deployment
         let deployment_fd = deployment_fd(sysroot, deployment)?;
         let sepolicy = crate::lsm::new_sepolicy_at(deployment_fd)?;
@@ -304,5 +321,12 @@ pub(crate) async fn impl_completion(
             .context("pulling bound images")?;
     }
 
+    // Log completion success
+    tracing::info!(
+        message_id = COMPLETION_JOURNAL_ID,
+        bootc.stateroot = stateroot.unwrap_or("default"),
+        "Successfully completed bootc installation"
+    );
+
     Ok(())
 }