From bf74ecbcc3fdefeaab598cb3fb6d06d926691021 Mon Sep 17 00:00:00 2001 From: gursewak1997 Date: Fri, 29 Aug 2025 11:31:31 -0700 Subject: [PATCH] Add systemd structured logging for bootc state changes --- Cargo.lock | 12 +++ Cargo.toml | 1 + crates/lib/src/boundimage.rs | 18 +++- crates/lib/src/cli.rs | 20 ++++ crates/lib/src/deploy.rs | 106 +++++++++++++++++++--- crates/lib/src/install.rs | 82 +++++++++++++++++ crates/lib/src/install/completion.rs | 26 +++++- crates/ostree-ext/src/container/deploy.rs | 13 +++ crates/utils/Cargo.toml | 1 + crates/utils/src/tracing_util.rs | 38 ++++++-- 10 files changed, 292 insertions(+), 25 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 76b8b764a..452ec7e1b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -234,6 +234,7 @@ dependencies = [ "tempfile", "tokio", "tracing", + "tracing-journald", "tracing-subscriber", ] @@ -2853,6 +2854,17 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-journald" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fc0b4143302cf1022dac868d521e36e8b27691f72c84b3311750d5188ebba657" +dependencies = [ + "libc", + "tracing-core", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.2.0" diff --git a/Cargo.toml b/Cargo.toml index 80949133a..c488a7ceb 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -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" diff --git a/crates/lib/src/boundimage.rs b/crates/lib/src/boundimage.rs index 9eba4517c..a515740bf 100644 --- a/crates/lib/src/boundimage.rs +++ b/crates/lib/src/boundimage.rs @@ -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 } diff --git a/crates/lib/src/cli.rs b/crates/lib/src/cli.rs index 7c31cca8d..a8fc1bf4a 100644 --- a/crates/lib/src/cli.rs +++ b/crates/lib/src/cli.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?; diff --git a/crates/lib/src/deploy.rs b/crates/lib/src/deploy.rs index 1d5a5256d..1b25d0340 100644 --- a/crates/lib/src/deploy.rs +++ b/crates/lib/src/deploy.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> { 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 { // Implementation of `bootc switch --in-place` pub(crate) fn switch_origin_inplace(root: &Dir, imgref: &ImageReference) -> Result { + // 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(); diff --git a/crates/lib/src/install.rs b/crates/lib/src/install.rs index 47e46cccc..156270dd2 100644 --- a/crates/lib/src/install.rs +++ b/crates/lib/src/install.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,6 +2021,16 @@ 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)?; @@ -1966,6 +2040,14 @@ pub(crate) async fn install_finalize(target: &Utf8Path) -> Result<()> { anyhow::bail!("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 diff --git a/crates/lib/src/install/completion.rs b/crates/lib/src/install/completion.rs index d834e7024..a1b69bd59 100644 --- a/crates/lib/src/install/completion.rs +++ b/crates/lib/src/install/completion.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(()) } diff --git a/crates/ostree-ext/src/container/deploy.rs b/crates/ostree-ext/src/container/deploy.rs index fa10480d8..b93df17aa 100644 --- a/crates/ostree-ext/src/container/deploy.rs +++ b/crates/ostree-ext/src/container/deploy.rs @@ -70,6 +70,19 @@ pub async fn deploy( imgref: &OstreeImageReference, options: Option>, ) -> Result> { + // Log the deployment operation to systemd journal (Debug level since staging already logged the main info) + + const DEPLOY_JOURNAL_ID: &str = "9e8d7c6b5a4f3e2d1c0b9a8f7e6d5c4b3"; + + tracing::debug!( + message_id = DEPLOY_JOURNAL_ID, + bootc.image.reference = &imgref.imgref.name, + bootc.image.transport = &imgref.imgref.transport.to_string(), + bootc.stateroot = stateroot, + "Deploying container image to OSTree: {}", + imgref + ); + let cancellable = ostree::gio::Cancellable::NONE; let options = options.unwrap_or_default(); let repo = &sysroot.repo(); diff --git a/crates/utils/Cargo.toml b/crates/utils/Cargo.toml index cac488a7b..aec5ad8c6 100644 --- a/crates/utils/Cargo.toml +++ b/crates/utils/Cargo.toml @@ -18,6 +18,7 @@ tempfile = { workspace = true } tokio = { workspace = true, features = ["process", "rt", "macros"] } tracing = { workspace = true } tracing-subscriber = { workspace = true } +tracing-journald = { workspace = true } [dev-dependencies] similar-asserts = { workspace = true } diff --git a/crates/utils/src/tracing_util.rs b/crates/utils/src/tracing_util.rs index 41eea6feb..38fd561ad 100644 --- a/crates/utils/src/tracing_util.rs +++ b/crates/utils/src/tracing_util.rs @@ -1,19 +1,41 @@ //! Helpers related to tracing, used by main entrypoints +use tracing_subscriber::prelude::*; + /// Initialize tracing with the default configuration. pub fn initialize_tracing() { - // Don't include timestamps and such because they're not really useful and - // too verbose, and plus several log targets such as journald will already - // include timestamps. + // Always try to use journald subscriber if we're running under systemd + // This ensures key messages (info, warn, error) go to the journal + let journald_layer = if let Ok(()) = std::env::var("JOURNAL_STREAM").map(|_| ()) { + tracing_journald::layer() + .ok() + .map(|layer| layer.with_filter(tracing_subscriber::filter::LevelFilter::INFO)) + } else { + None + }; + + // Always add the stdout/stderr layer for RUST_LOG support + // This preserves the existing workflow for users let format = tracing_subscriber::fmt::format() .without_time() .with_target(false) .compact(); - // Log to stderr by default - tracing_subscriber::fmt() + + let fmt_layer = tracing_subscriber::fmt::layer() .event_format(format) .with_writer(std::io::stderr) - .with_max_level(tracing::Level::WARN) - .with_env_filter(tracing_subscriber::EnvFilter::from_default_env()) - .init(); + .with_filter(tracing_subscriber::EnvFilter::from_default_env()); + + // Build the registry with layers, handling the journald layer conditionally + match journald_layer { + Some(journald) => { + tracing_subscriber::registry() + .with(fmt_layer) + .with(journald) + .init(); + } + None => { + tracing_subscriber::registry().with(fmt_layer).init(); + } + } }