From 4cd63c92c58fcd260f30d887e8353a93acce1d91 Mon Sep 17 00:00:00 2001 From: "Sean P. Kelly" Date: Sun, 28 Jul 2024 03:15:43 +0000 Subject: [PATCH] improve logging in lock generation --- Cargo.lock | 1 + twoliter/Cargo.toml | 1 + twoliter/src/cargo_make.rs | 2 +- twoliter/src/common.rs | 26 ++++- twoliter/src/lock.rs | 209 ++++++++++++++++++++++++++++++++----- twoliter/src/project.rs | 9 +- twoliter/src/tools.rs | 2 +- 7 files changed, 220 insertions(+), 30 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 20852d433..d2acb4776 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3878,6 +3878,7 @@ dependencies = [ "testsys", "tokio", "toml", + "tracing", "tuftool", "unplug", "uuid", diff --git a/twoliter/Cargo.toml b/twoliter/Cargo.toml index 79d86bdf3..68a3998e5 100644 --- a/twoliter/Cargo.toml +++ b/twoliter/Cargo.toml @@ -31,6 +31,7 @@ tar = "0.4" tempfile = "3" tokio = { version = "1", default-features = false, features = ["fs", "macros", "process", "rt-multi-thread"] } toml = "0.8" +tracing = { version = "0.1", features = ["log"] } uuid = { version = "1", features = [ "v4" ] } # Binary dependencies. These are binaries that we want to embed in the Twoliter binary. diff --git a/twoliter/src/cargo_make.rs b/twoliter/src/cargo_make.rs index cb2e50ca5..a2898b54e 100644 --- a/twoliter/src/cargo_make.rs +++ b/twoliter/src/cargo_make.rs @@ -1,8 +1,8 @@ use crate::common::{exec_log, BUILDSYS_OUTPUT_GENERATION_ID}; use anyhow::{bail, Result}; -use log::trace; use std::path::PathBuf; use tokio::process::Command; +use tracing::trace; /// A struct used to invoke `cargo make` tasks with `twoliter`'s `Makefile.toml`. /// ```rust diff --git a/twoliter/src/common.rs b/twoliter/src/common.rs index 97bf3ed58..23928ac8a 100644 --- a/twoliter/src/common.rs +++ b/twoliter/src/common.rs @@ -1,6 +1,7 @@ use anyhow::{ensure, Context, Result}; -use log::{self, debug, LevelFilter}; +use log::{self, LevelFilter}; use tokio::process::Command; +use tracing::{debug, instrument}; /// This is passed as an environment variable to Buildsys. Buildsys tells Cargo to watch this /// environment variable for changes. So if we have a breaking change to the way Buildsys and/or @@ -10,6 +11,7 @@ pub(crate) const BUILDSYS_OUTPUT_GENERATION_ID: u32 = 1; /// Run a `tokio::process::Command` and return a `Result` letting us know whether or not it worked. /// Pipes stdout/stderr when logging `LevelFilter` is more verbose than `Warn`. +#[instrument(level = "trace", skip(cmd))] pub(crate) async fn exec_log(cmd: &mut Command) -> Result<()> { let quiet = matches!( log::max_level(), @@ -22,6 +24,7 @@ pub(crate) async fn exec_log(cmd: &mut Command) -> Result<()> { /// Run a `tokio::process::Command` and return a `Result` letting us know whether or not it worked. /// `quiet` determines whether or not the command output will be piped to `stdout/stderr`. When /// `quiet=true`, no output will be shown and will be returned instead. +#[instrument(level = "trace")] pub(crate) async fn exec(cmd: &mut Command, quiet: bool) -> Result> { debug!("Running: {:?}", cmd); Ok(if quiet { @@ -73,7 +76,9 @@ pub(crate) mod fs { use std::io::ErrorKind; use std::path::{Path, PathBuf}; use tokio::fs; + use tracing::instrument; + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn canonicalize(path: impl AsRef) -> Result { fs::canonicalize(path.as_ref()).await.context(format!( "Unable to canonicalize '{}'", @@ -81,6 +86,11 @@ pub(crate) mod fs { )) } + #[instrument( + level = "trace", + skip_all, + fields(from = %from.as_ref().display(), to = %to.as_ref().display()) + )] pub(crate) async fn copy(from: P1, to: P2) -> Result where P1: AsRef, @@ -95,6 +105,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn create_dir(path: impl AsRef) -> Result<()> { fs::create_dir(path.as_ref()).await.context(format!( "Unable to create directory '{}'", @@ -102,6 +113,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn create_dir_all(path: impl AsRef) -> Result<()> { fs::create_dir_all(path.as_ref()).await.context(format!( "Unable to create directory '{}'", @@ -109,6 +121,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn metadata(path: impl AsRef) -> Result { fs::metadata(path.as_ref()).await.context(format!( "Unable to read metadata for '{}'", @@ -116,12 +129,14 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn read(path: impl AsRef) -> Result> { fs::read(path.as_ref()) .await .context(format!("Unable to read from '{}'", path.as_ref().display())) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn read_to_string(path: impl AsRef) -> Result { fs::read_to_string(path.as_ref()).await.context(format!( "Unable to read the following file as a string '{}'", @@ -129,6 +144,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn remove_dir(path: impl AsRef) -> Result<()> { fs::remove_dir(path.as_ref()).await.context(format!( "Unable to remove directory (remove_dir) '{}'", @@ -136,6 +152,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn remove_dir_all(path: impl AsRef) -> Result<()> { match fs::remove_dir_all(path.as_ref()).await { Ok(_) => Ok(()), @@ -152,6 +169,11 @@ pub(crate) mod fs { } } + #[instrument( + level = "trace", + skip_all, + fields(from = %from.as_ref().display(), to = %to.as_ref().display()) + )] pub(crate) async fn rename(from: impl AsRef, to: impl AsRef) -> Result<()> { let from = from.as_ref(); let to = to.as_ref(); @@ -162,6 +184,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip(path), fields(path = %path.as_ref().display()))] pub(crate) async fn remove_file(path: impl AsRef) -> Result<()> { fs::remove_file(path.as_ref()).await.context(format!( "Unable to remove file '{}'", @@ -169,6 +192,7 @@ pub(crate) mod fs { )) } + #[instrument(level = "trace", skip_all, fields(path = %path.as_ref().display()))] pub(crate) async fn write(path: P, contents: C) -> Result<()> where P: AsRef, diff --git a/twoliter/src/lock.rs b/twoliter/src/lock.rs index 782fea616..bd5a89501 100644 --- a/twoliter/src/lock.rs +++ b/twoliter/src/lock.rs @@ -1,8 +1,10 @@ use crate::common::fs::{create_dir_all, read, remove_dir_all, remove_file, write}; use crate::project::{Image, Project, ValidIdentifier, Vendor}; use crate::schema_version::SchemaVersion; -use anyhow::{ensure, Context, Result}; +use anyhow::{bail, ensure, Context, Result}; use base64::Engine; +use futures::pin_mut; +use futures::stream::{self, StreamExt, TryStreamExt}; use oci_cli_wrapper::{DockerArchitecture, ImageTool}; use olpc_cjson::CanonicalFormatter as CanonicalJsonFormatter; use semver::Version; @@ -11,13 +13,15 @@ use serde::{Deserialize, Deserializer, Serialize}; use sha2::Digest; use std::cmp::PartialEq; use std::collections::{HashMap, HashSet}; -use std::fmt::{Display, Formatter}; +use std::fmt::{Debug, Display, Formatter}; use std::fs::File; use std::hash::{Hash, Hasher}; use std::mem::take; use std::path::{Path, PathBuf}; +use std::sync::Arc; use tar::Archive as TarArchive; use tokio::fs::read_to_string; +use tracing::{debug, error, info, instrument, trace}; const TWOLITER_LOCK: &str = "Twoliter.lock"; @@ -41,11 +45,18 @@ pub(crate) struct LockedImage { impl LockedImage { pub async fn new(image_tool: &ImageTool, vendor: &Vendor, image: &Image) -> Result { let source = format!("{}/{}:v{}", vendor.registry, image.name, image.version); + debug!("Pulling image manifest for locked image '{}'", source); let manifest_bytes = image_tool.get_manifest(source.as_str()).await?; // We calculate a 'digest' of the manifest to use as our unique id let digest = sha2::Sha256::digest(manifest_bytes.as_slice()); let digest = base64::engine::general_purpose::STANDARD.encode(digest.as_slice()); + trace!( + "Calculated digest for locked image '{}': '{}'", + source, + digest + ); + Ok(Self { name: image.name.to_string(), version: image.version.clone(), @@ -82,7 +93,7 @@ impl Hash for LockedImage { } } -#[derive(Deserialize, Debug)] +#[derive(Deserialize, Debug, Clone)] struct ImageMetadata { /// The name of the kit #[allow(dead_code)] @@ -97,6 +108,69 @@ struct ImageMetadata { pub kits: Vec, } +impl TryFrom for ImageMetadata { + type Error = anyhow::Error; + + fn try_from(value: EncodedKitMetadata) -> Result { + let bytes = base64::engine::general_purpose::STANDARD + .decode(value.0) + .context("failed to decode kit metadata as base64")?; + serde_json::from_slice(bytes.as_slice()).context("failed to parse kit metadata json") + } +} + +/// Encoded kit metadata, which is embedded in a label of the OCI image config. +#[derive(Clone, Eq, PartialEq)] +struct EncodedKitMetadata(String); + +impl EncodedKitMetadata { + #[instrument(level = "trace")] + async fn try_from_image(image_uri: &str, image_tool: &ImageTool) -> Result { + trace!(image_uri, "Extracting kit metadata from OCI image config"); + let config = image_tool.get_config(image_uri).await?; + let kit_metadata = EncodedKitMetadata( + config + .labels + .get("dev.bottlerocket.kit.v1") + .context("no metadata stored on image, this image appears to not be a kit")? + .to_owned(), + ); + + trace!( + image_uri, + image_config = ?config, + ?kit_metadata, + "Kit metadata retrieved from image config" + ); + + Ok(kit_metadata) + } + + /// Infallible method to provide debugging insights into encoded `ImageMetadata` + /// + /// Shows a `Debug` view of the encoded `ImageMetadata` if possible, otherwise shows + /// the encoded form. + fn try_debug_image_metadata(&self) -> String { + self.debug_image_metadata().unwrap_or_else(|| { + format!("", self.0.replace("\n", "\\n")) + }) + } + + fn debug_image_metadata(&self) -> Option { + base64::engine::general_purpose::STANDARD + .decode(&self.0) + .ok() + .and_then(|bytes| serde_json::from_slice(bytes.as_slice()).ok()) + .map(|metadata: ImageMetadata| format!("", metadata)) + } +} + +impl Debug for EncodedKitMetadata { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.try_debug_image_metadata()) + } +} + #[derive(Deserialize, Debug)] struct ManifestListView { manifests: Vec, @@ -183,7 +257,9 @@ impl OCIArchive { self.cache_dir.join(self.digest.replace(':', "-")) } + #[instrument(level = "trace", skip_all, fields(image = %self.image))] async fn pull_image(&self, image_tool: &ImageTool) -> Result<()> { + debug!("Pulling image '{}'", self.image); let digest_uri = self.image.digest_uri(self.digest.as_str()); let oci_archive_path = self.archive_path(); if !oci_archive_path.exists() { @@ -191,10 +267,17 @@ impl OCIArchive { image_tool .pull_oci_image(oci_archive_path.as_path(), digest_uri.as_str()) .await?; + } else { + debug!("Image '{}' already present -- no need to pull.", self.image); } Ok(()) } + #[instrument( + level = "trace", + skip_all, + fields(image = %self.image, out_dir = %out_dir.as_ref().display()), + )] async fn unpack_layers

(&self, out_dir: P) -> Result<()> where P: AsRef, @@ -207,10 +290,16 @@ impl OCIArchive { digest_file.display() ))?; if digest == self.digest { + trace!( + "Found existing digest file for image '{}' at '{}'", + self.image, + digest_file.display() + ); return Ok(()); } } + debug!("Unpacking layers for image '{}'", self.image); remove_dir_all(path).await?; create_dir_all(path).await?; let index_bytes = read(self.archive_path().join("index.json")).await?; @@ -218,6 +307,7 @@ impl OCIArchive { .context("failed to deserialize oci image index")?; // Read the manifest so we can get the layer digests + trace!(image = %self.image, "Extracting layer digests from image manifest"); let digest = index .manifests .first() @@ -231,6 +321,7 @@ impl OCIArchive { .context("failed to deserialize oci manifest")?; // Extract each layer into the target directory + trace!(image = %self.image, "Extracting image layers"); for layer in manifest_layout.layers { let digest = layer.digest.to_string().replace(':', "/"); let layer_blob = File::open(self.archive_path().join(format!("blobs/{digest}"))) @@ -269,9 +360,11 @@ pub(crate) struct Lock { #[allow(dead_code)] impl Lock { + #[instrument(level = "trace", skip(project))] pub(crate) async fn load(project: &Project) -> Result { let lock_file_path = project.project_dir().join(TWOLITER_LOCK); if lock_file_path.exists() { + debug!("Loading existing lockfile '{}'", lock_file_path.display()); let lock_str = read_to_string(&lock_file_path) .await .context("failed to read lockfile")?; @@ -284,13 +377,19 @@ impl Lock { Self::create(project).await } + #[instrument(level = "trace", skip(project))] pub(crate) async fn create(project: &Project) -> Result { let lock_file_path = project.project_dir().join(TWOLITER_LOCK); if lock_file_path.exists() { + debug!("Removing existing lock file '{}'", lock_file_path.display()); remove_file(&lock_file_path).await?; } + + info!("Resolving project references to create lock file"); let lock = Self::resolve(project).await?; let lock_str = toml::to_string(&lock).context("failed to serialize lock file")?; + + debug!("Writing new lock file to '{}'", lock_file_path.display()); write(&lock_file_path, lock_str) .await .context("failed to write lock file")?; @@ -305,6 +404,7 @@ impl Lock { } /// Fetches all external kits defined in a Twoliter.lock to the build directory + #[instrument(level = "trace", skip_all)] pub(crate) async fn fetch(&self, project: &Project, arch: &str) -> Result<()> { let image_tool = ImageTool::from_environment()?; let target_dir = project.external_kits_dir(); @@ -312,6 +412,11 @@ impl Lock { "failed to create external-kits directory at {}", target_dir.display() ))?; + + info!( + dependencies = ?self.kit.iter().map(ToString::to_string).collect::>(), + "Extracting kit dependencies." + ); for image in self.kit.iter() { self.extract_kit(&image_tool, &project.external_kits_dir(), image, arch) .await?; @@ -344,6 +449,7 @@ impl Lock { Ok(()) } + #[instrument(level = "trace", skip(image), fields(image = %image))] async fn get_manifest( &self, image_tool: &ImageTool, @@ -365,6 +471,11 @@ impl Lock { )) } + #[instrument( + level = "trace", + skip(image), + fields(image = %image, path = %path.as_ref().display()) + )] async fn extract_kit

( &self, image_tool: &ImageTool, @@ -375,6 +486,11 @@ impl Lock { where P: AsRef, { + info!( + "Extracting kit '{}' to '{}'", + image, + path.as_ref().display() + ); let vendor = image.vendor.clone(); let name = image.name.clone(); let target_path = path.as_ref().join(format!("{vendor}/{name}/{arch}")); @@ -396,6 +512,7 @@ impl Lock { Ok(()) } + #[instrument(level = "trace", skip(project))] async fn resolve(project: &Project) -> Result { let vendor_table = project.vendor(); let mut known: HashMap<(ValidIdentifier, ValidIdentifier), Version> = HashMap::new(); @@ -411,6 +528,7 @@ impl Lock { while !remaining.is_empty() { let working_set: Vec<_> = take(&mut remaining); for image in working_set.iter() { + debug!(%image, "Resolving kit '{}'", image.name); if let Some(version) = known.get(&(image.name.clone(), image.vendor.clone())) { let name = image.name.clone(); let left_version = image.version.clone(); @@ -419,6 +537,10 @@ impl Lock { image.version == *version, "cannot have multiple versions of the same kit ({name}-{left_version}@{vendor} != {name}-{version}@{vendor}", ); + debug!( + ?image, + "Skipping kit '{}' as it has already been resolved", image.name + ); continue; } let vendor = vendor_table.get(&image.vendor).context(format!( @@ -438,12 +560,14 @@ impl Lock { } } } + + debug!(?sdk_set, "Resolving workspace SDK"); ensure!( sdk_set.len() <= 1, "cannot use multiple sdks (found sdk: {})", sdk_set .iter() - .map(|x| format!("{}-{}@{}", x.name, x.version, x.vendor)) + .map(ToString::to_string) .collect::>() .join(", ") ); @@ -464,38 +588,71 @@ impl Lock { }) } + #[instrument(level = "trace", skip(image), fields(image = %image))] async fn find_kit( image_tool: &ImageTool, vendor: &Vendor, image: &LockedImage, ) -> Result { + debug!(kit_image = %image, "Searching for kit"); let manifest_list: ManifestListView = serde_json::from_slice(image.manifest.as_slice()) .context("failed to deserialize manifest list")?; - let mut encoded_metadata: Option = None; - for manifest in manifest_list.manifests.iter() { - let image_uri = format!("{}/{}@{}", vendor.registry, image.name, manifest.digest); - - // Now we want to fetch the metadata from the OCI image config - let config = image_tool.get_config(image_uri.as_str()).await?; - let encoded = config - .labels - .get("dev.bottlerocket.kit.v1") - .context("no metadata stored on image, this image appears to not be a kit")?; - if let Some(metadata) = encoded_metadata.as_ref() { - ensure!( - encoded == metadata, - "metadata does match between images in manifest list" + trace!(manifest_list = ?manifest_list, "Deserialized manifest list"); + debug!("Extracting kit metadata from OCI image"); + let embedded_kit_metadata = + stream::iter(manifest_list.manifests).then(|manifest| async move { + let image_uri = format!("{}/{}@{}", vendor.registry, image.name, manifest.digest); + EncodedKitMetadata::try_from_image(&image_uri, image_tool).await + }); + pin_mut!(embedded_kit_metadata); + + let canonical_metadata = embedded_kit_metadata + .try_next() + .await? + .context(format!("could not find metadata for kit {}", image))?; + + trace!("Checking that all manifests refer to the same kit."); + while let Some(kit_metadata) = embedded_kit_metadata.try_next().await? { + if kit_metadata != canonical_metadata { + error!( + ?canonical_metadata, + ?kit_metadata, + "Mismatched kit metadata in manifest list" ); - } else { - encoded_metadata = Some(encoded.clone()); + bail!("Metadata does not match between images in manifest list"); } } - let encoded = - encoded_metadata.context(format!("could not find metadata for kit {}", image))?; - let decoded = base64::engine::general_purpose::STANDARD - .decode(encoded.as_str()) - .context("malformed kit metadata detected")?; - serde_json::from_slice(decoded.as_slice()).context("malformed kit metadata json") + canonical_metadata + .try_into() + .context("Failed to decode and parse kit metadata") + } +} + +#[cfg(test)] +mod test { + use super::*; + #[test] + fn test_try_debug_image_metadata_succeeds() { + // Given a valid encoded metadata string, + // When we attempt to decode it for debugging, + // Then the debug string is marked as having been decoded. + let encoded = EncodedKitMetadata( + "eyJraXQiOltdLCJuYW1lIjoiYm90dGxlcm9ja2V0LWNvcmUta2l0Iiwic2RrIjp7ImRpZ2VzdCI6ImlyY09EUl\ + d3ZmxjTTdzaisrMmszSk5RWkovb3ZDUVRpUlkrRFpvaGdrNlk9IiwibmFtZSI6InRoYXItYmUtYmV0YS1zZGsiL\ + CJzb3VyY2UiOiJwdWJsaWMuZWNyLmF3cy91MWczYzh6NC90aGFyLWJlLWJldGEtc2RrOnYwLjQzLjAiLCJ2ZW5k\ + b3IiOiJib3R0bGVyb2NrZXQtbmV3IiwidmVyc2lvbiI6IjAuNDMuMCJ9LCJ2ZXJzaW9uIjoiMi4wLjAifQo=" + .to_string() + ); + assert!(encoded.debug_image_metadata().is_some()); + } + + #[test] + fn test_try_debug_image_metadata_fails() { + // Given an invalid encoded metadata string, + // When we attempt to decode it for debugging, + // Then the debug string is marked as remaining encoded. + let junk_data = EncodedKitMetadata("abcdefghijklmnophello".to_string()); + assert!(junk_data.debug_image_metadata().is_none()); } } diff --git a/twoliter/src/project.rs b/twoliter/src/project.rs index 46c97f176..a1763f64b 100644 --- a/twoliter/src/project.rs +++ b/twoliter/src/project.rs @@ -7,7 +7,6 @@ use async_walkdir::WalkDir; use base64::Engine; use buildsys_config::{EXTERNAL_KIT_DIRECTORY, EXTERNAL_KIT_METADATA}; use futures::stream::StreamExt; -use log::{debug, info, trace, warn}; use semver::Version; use serde::de::Error; use serde::{Deserialize, Deserializer, Serialize, Serializer}; @@ -19,10 +18,12 @@ use std::hash::Hash; use std::io::Write; use std::path::{Path, PathBuf}; use toml::Table; +use tracing::{debug, info, instrument, trace, warn}; /// Common functionality in commands, if the user gave a path to the `Twoliter.toml` file, /// we use it, otherwise we search for the file. Returns the `Project` and the path at which it was /// found (this is the same as `user_path` if provided). +#[instrument(level = "trace")] pub(crate) async fn load_or_find_project(user_path: Option) -> Result { let project = match user_path { None => Project::find_and_load(".").await?, @@ -305,6 +306,12 @@ pub(crate) struct Image { pub vendor: ValidIdentifier, } +impl Display for Image { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + write!(f, "{}-{}@{}", self.name, self.version, self.vendor) + } +} + /// This is used to `Deserialize` a project, then run validation code before returning a valid /// [`Project`]. This is necessary both because there is no post-deserialization serde hook for /// validation and, even if there was, we need to know the project directory path in order to check diff --git a/twoliter/src/tools.rs b/twoliter/src/tools.rs index a379dfe73..5f8d50cfc 100644 --- a/twoliter/src/tools.rs +++ b/twoliter/src/tools.rs @@ -2,12 +2,12 @@ use crate::common::fs; use anyhow::{Context, Result}; use filetime::{set_file_handle_times, set_file_mtime, FileTime}; use flate2::read::ZlibDecoder; -use log::debug; use std::path::Path; use tar::Archive; use tokio::fs::OpenOptions; use tokio::io::AsyncWriteExt; use tokio::runtime::Handle; +use tracing::debug; const TAR_GZ_DATA: &[u8] = include_bytes!(concat!(env!("OUT_DIR"), "/tools.tar.gz")); const BOTTLEROCKET_VARIANT: &[u8] =