diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 95d98270..bcc55a01 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -74,3 +74,21 @@ jobs: # TODO: Switch this back to using the `alpine` tag once the stable Pack CLI release supports # image extensions (currently newer sample alpine images fail to build with stable Pack). run: pack build example-basics --builder cnbs/sample-builder@sha256:da5ff69191919f1ff30d5e28859affff8e39f23038137c7751e24a42e919c1ab --trust-builder --buildpack packaged/x86_64-unknown-linux-musl/debug/libcnb-examples_basics --path examples/ + + print-style-guide: + runs-on: ubuntu-22.04 + steps: + - name: Checkout + uses: actions/checkout@v4 + - name: Install musl-tools + run: sudo apt-get install musl-tools --no-install-recommends + - name: Update Rust toolchain + run: rustup update + - name: Install Rust linux-musl target + run: rustup target add x86_64-unknown-linux-musl + - name: Rust Cache + uses: Swatinem/rust-cache@v2.7.1 + - name: Install Pack CLI + uses: buildpacks/github-actions/setup-pack@v5.5.0 + - name: PRINT style guide + run: cargo run --example print_style_guide diff --git a/CHANGELOG.md b/CHANGELOG.md index 82610c45..6bd401cd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +- `libherokubuildpack`: + - Added build `output` module. This will help buildpack authors provide consistent and delightful output to their buildpack users ([#721](https://github.com/heroku/libcnb.rs/pull/721)) ## [0.15.0] - 2023-09-25 diff --git a/libherokubuildpack/Cargo.toml b/libherokubuildpack/Cargo.toml index 56a3afa3..6babc334 100644 --- a/libherokubuildpack/Cargo.toml +++ b/libherokubuildpack/Cargo.toml @@ -14,8 +14,22 @@ include = ["src/**/*", "LICENSE", "README.md"] [package.metadata.docs.rs] all-features = true +[[example]] +name = "print_style_guide" + [features] -default = ["command", "download", "digest", "error", "log", "tar", "toml", "fs", "write"] +default = [ + "command", + "download", + "digest", + "error", + "log", + "tar", + "toml", + "fs", + "write", + "output", +] download = ["dep:ureq", "dep:thiserror"] digest = ["dep:sha2"] error = ["log", "dep:libcnb"] @@ -24,6 +38,7 @@ tar = ["dep:tar", "dep:flate2"] toml = ["dep:toml"] fs = ["dep:pathdiff"] command = ["write", "dep:crossbeam-utils"] +output = ["dep:lazy_static", "dep:regex", "dep:const_format"] write = [] [dependencies] @@ -42,6 +57,14 @@ termcolor = { version = "1.3.0", optional = true } thiserror = { version = "1.0.48", optional = true } toml = { workspace = true, optional = true } ureq = { version = "2.7.1", default-features = false, features = ["tls"], optional = true } +lazy_static = { version = "1", optional = true } +regex = { version = "1", optional = true } +const_format = { version = "0.2", optional = true } [dev-dependencies] tempfile = "3.8.0" +libcnb-test = "0.15.0" +indoc = "2" +pretty_assertions = "1" +fun_run = "0.1.1" +ascii_table = { version = "4", features = ["color_codes"] } diff --git a/libherokubuildpack/examples/print_style_guide.rs b/libherokubuildpack/examples/print_style_guide.rs new file mode 100644 index 00000000..7dc6a512 --- /dev/null +++ b/libherokubuildpack/examples/print_style_guide.rs @@ -0,0 +1,205 @@ +use ascii_table::AsciiTable; +use fun_run::CommandWithName; +use indoc::formatdoc; +use libherokubuildpack::output::style::{self, DEBUG_INFO, HELP}; +use libherokubuildpack::output::{ + build_log::*, + section_log::{log_step, log_step_stream, log_step_timed}, +}; +use std::io::stdout; +use std::process::Command; + +fn main() { + println!( + "{}", + formatdoc! {" + + Living build output style guide + =============================== + "} + ); + + { + let mut log = BuildLog::new(stdout()).buildpack_name("Section logging features"); + log = log + .section("Section heading example") + .step("step example") + .step("step example two") + .end_section(); + + log = log + .section("Section and step description") + .step( + "A section should be a noun i.e. 'Ruby Version', consider this the section topic.", + ) + .step("A step should be a verb i.e. 'Downloading'") + .step("Related verbs should be nested under a single section") + .step( + formatdoc! {" + Steps can be multiple lines long + However they're best as short, factual, + descriptions of what the program is doing. + "} + .trim(), + ) + .step("Prefer a single line when possible") + .step("Sections and steps are sentence cased with no ending puncuation") + .step(&format!("{HELP} capitalize the first letter")) + .end_section(); + + let mut command = Command::new("bash"); + command.args(["-c", "ps aux | grep cargo"]); + + let mut stream = log.section("Timer steps") + .step("Long running code should execute with a timer printing to the UI, to indicate the progam did not hang.") + .step("Example:") + .step_timed("Background progress timer") + .finish_timed_step() + .step("Output can be streamed. Mostly from commands. Example:") + .step_timed_stream(&format!("Running {}", style::command(command.name()))); + + command.stream_output(stream.io(), stream.io()).unwrap(); + log = stream.finish_timed_stream().end_section(); + drop(log); + } + + { + let mut log = BuildLog::new(stdout()).buildpack_name("Section log functions"); + log = log + .section("Logging inside a layer") + .step( + formatdoc! {" + Layer interfaces are neither mutable nor consuming i.e. + + ``` + fn create( + &self, + _context: &BuildContext, + layer_path: &Path, + ) -> Result, RubyBuildpackError> + ``` + + To allow logging within a layer you can use the `output::section_log` interface. + "} + .trim_end(), + ) + .step("This `section_log` inteface allows you to log without state") + .step("That means you're responsonsible creating a section before calling it") + .step("Here's an example") + .end_section(); + + let section_log = log.section("Example:"); + + log_step("log_step()"); + log_step_timed("log_step_timed()", || { + // do work here + }); + log_step_stream("log_step_stream()", |stream| { + Command::new("bash") + .args(["-c", "ps aux | grep cargo"]) + .stream_output(stream.io(), stream.io()) + .unwrap() + }); + log_step(formatdoc! {" + If you want to help make sure you're within a section then you can require your layer + takes a reference to `&'a dyn SectionLogger` + "}); + section_log.end_section(); + } + + { + let cmd_error = Command::new("iDoNotExist").named_output().err().unwrap(); + + let mut log = BuildLog::new(stdout()).buildpack_name("Error and warnings"); + log = log + .section("Debug information") + .step("Should go above errors in section/step format") + .end_section(); + + log = log + .section(DEBUG_INFO) + .step(&cmd_error.to_string()) + .end_section(); + + log.announce() + .warning(&formatdoc! {" + Warning: This is a warning header + + This is a warning body. Warnings are for when we know for a fact a problem exists + but it's not bad enough to abort the build. + "}) + .important(&formatdoc! {" + Important: This is important + + Important is for when there's critical information that needs to be read + however it may or may not be a problem. If we know for a fact that there's + a problem then use a warning instead. + + An example of something that is important but might not be a problem is + that an application owner upgraded to a new stack. + "}) + .error(&formatdoc! {" + Error: This is an error header + + This is the error body. Use an error for when the build cannot continue. + An error should include a header with a short description of why it cannot continue. + + The body should include what error state was observed, why that's a problem, and + what remediation steps an application owner using the buildpack to deploy can + take to solve the issue. + "}); + } + + { + let mut log = BuildLog::new(stdout()).buildpack_name("Formatting helpers"); + + log = log + .section("The style module") + .step(&formatdoc! {" + Formatting helpers can be used to enhance log output: + "}) + .end_section(); + + let mut table = AsciiTable::default(); + table.set_max_width(240); + table.column(0).set_header("Example"); + table.column(1).set_header("Code"); + table.column(2).set_header("When to use"); + + let data: Vec> = vec![ + vec![ + style::value("2.3.4"), + "style::value(\"2.3.f\")".to_string(), + "With versions, file names or other important values worth highlighting".to_string(), + ], + vec![ + style::url("https://www.schneems.com"), + "style::url(\"https://www.schneems.com\")".to_string(), + "With urls".to_string(), + ], + vec![ + style::command("bundle install"), + "style::command(command.name())".to_string(), + "With commands (alongside of `fun_run::CommandWithName`)".to_string(), + ], + vec![ + style::details("extra information"), + "style::details(\"extra information\")".to_string(), + "Add specific information at the end of a line i.e. 'Cache cleared (ruby version changed)'".to_string() + ], + vec![ + style::HELP.to_string(), + "style::HELP.to_string()".to_string(), + "A help prefix, use it in a step or section title".to_string() + ], + vec![ + style::DEBUG_INFO.to_string(), + "style::DEBUG_INFO.to_string()".to_string(), + "A debug prefix, use it in a step or section title".to_string() + ] + ]; + + table.print(data); + drop(log); + } +} diff --git a/libherokubuildpack/src/lib.rs b/libherokubuildpack/src/lib.rs index faca25ba..1b46d087 100644 --- a/libherokubuildpack/src/lib.rs +++ b/libherokubuildpack/src/lib.rs @@ -21,9 +21,16 @@ pub mod error; pub mod fs; #[cfg(feature = "log")] pub mod log; +#[cfg(feature = "output")] +pub mod output; #[cfg(feature = "tar")] pub mod tar; #[cfg(feature = "toml")] pub mod toml; #[cfg(feature = "write")] pub mod write; + +#[cfg(test)] +use ascii_table as _; +#[cfg(test)] +use fun_run as _; diff --git a/libherokubuildpack/src/output/background_timer.rs b/libherokubuildpack/src/output/background_timer.rs new file mode 100644 index 00000000..f3c7f187 --- /dev/null +++ b/libherokubuildpack/src/output/background_timer.rs @@ -0,0 +1,157 @@ +use std::io::Write; +use std::sync::mpsc::Sender; +use std::sync::{mpsc, Arc, Mutex}; +use std::thread::JoinHandle; +use std::time::{Duration, Instant}; + +/// This module is responsible for the logic involved in the printing to output while +/// other work is being performed. + +/// Prints a start, then a tick every second, and an end to the given `Write` value. +/// +/// Returns a struct that allows for manually stopping the timer or will automatically stop +/// the timer if the guard is dropped. This functionality allows for errors that trigger +/// an exit of the function to not accidentally have a timer printing in the background +/// forever. +pub(crate) fn start_timer( + arc_io: &Arc>, + tick_duration: Duration, + start: impl AsRef, + tick: impl AsRef, + end: impl AsRef, +) -> StopJoinGuard +where + // The 'static lifetime means as long as something holds a reference to it, nothing it references + // will go away. + // + // From https://users.rust-lang.org/t/why-does-thread-spawn-need-static-lifetime-for-generic-bounds/4541 + // + // [lifetimes] refer to the minimum possible lifetime of any borrowed references that the object contains. + T: Write + Send + Sync + 'static, +{ + let instant = Instant::now(); + let (sender, receiver) = mpsc::channel::<()>(); + let start = start.as_ref().to_string(); + let tick = tick.as_ref().to_string(); + let end = end.as_ref().to_string(); + + let arc_io = arc_io.clone(); + let handle = std::thread::spawn(move || { + let mut io = arc_io.lock().expect("Logging mutex poisoned"); + write!(&mut io, "{start}").expect("Internal error"); + io.flush().expect("Internal error"); + loop { + write!(&mut io, "{tick}").expect("Internal error"); + io.flush().expect("Internal error"); + + if receiver.recv_timeout(tick_duration).is_ok() { + write!(&mut io, "{end}").expect("Internal error"); + io.flush().expect("Internal error"); + break; + } + } + }); + + StopJoinGuard { + inner: Some(StopTimer { + handle: Some(handle), + sender: Some(sender), + instant, + }), + } +} + +/// Responsible for stopping a running timer thread +#[derive(Debug)] +pub(crate) struct StopTimer { + instant: Instant, + handle: Option>, + sender: Option>, +} + +impl StopTimer { + pub(crate) fn elapsed(&self) -> Duration { + self.instant.elapsed() + } +} + +pub(crate) trait StopJoin: std::fmt::Debug { + fn stop_join(self) -> Self; +} + +impl StopJoin for StopTimer { + fn stop_join(mut self) -> Self { + if let Some(inner) = self.sender.take() { + inner.send(()).expect("Internal error"); + } + + if let Some(inner) = self.handle.take() { + inner.join().expect("Internal error"); + } + + self + } +} + +// Guarantees that stop is called on the inner +#[derive(Debug)] +pub(crate) struct StopJoinGuard { + inner: Option, +} + +impl StopJoinGuard { + /// Since this consumes self and `stop_join` consumes + /// the inner, the option will never be empty unless + /// it was created with a None inner. + /// + /// Since inner is private we guarantee it's always Some + /// until this struct is consumed. + pub(crate) fn stop(mut self) -> T { + self.inner + .take() + .map(StopJoin::stop_join) + .expect("Internal error: Should never panic, codepath tested") + } +} + +impl Drop for StopJoinGuard { + fn drop(&mut self) { + if let Some(inner) = self.inner.take() { + inner.stop_join(); + } + } +} + +#[cfg(test)] +mod test { + use super::*; + use crate::output::util::ReadYourWrite; + use libcnb_test::assert_contains; + use std::thread::sleep; + + #[test] + fn does_stop_does_not_panic() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let done = start_timer(&writer.arc_io(), Duration::from_millis(1), " .", ".", ". "); + + let _ = done.stop(); + + assert_contains!(String::from_utf8_lossy(&reader.lock().unwrap()), " ... "); + } + + #[test] + fn test_drop_stops_timer() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let done = start_timer(&writer.arc_io(), Duration::from_millis(1), " .", ".", ". "); + + drop(done); + sleep(Duration::from_millis(2)); + + let before = String::from_utf8_lossy(&reader.lock().unwrap()).to_string(); + sleep(Duration::from_millis(100)); + let after = String::from_utf8_lossy(&reader.lock().unwrap()).to_string(); + assert_eq!(before, after); + } +} diff --git a/libherokubuildpack/src/output/build_log.rs b/libherokubuildpack/src/output/build_log.rs new file mode 100644 index 00000000..c7564aa1 --- /dev/null +++ b/libherokubuildpack/src/output/build_log.rs @@ -0,0 +1,710 @@ +use crate::output::background_timer::{start_timer, StopJoinGuard, StopTimer}; +#[allow(clippy::wildcard_imports)] +pub use crate::output::interface::*; +use crate::output::style; +use std::fmt::Debug; +use std::io::Write; +use std::marker::PhantomData; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +/// # Build output logging +/// +/// Use the `BuildLog` to output structured text as a buildpack is executing +/// +/// ``` +/// use libherokubuildpack::output::build_log::*; +/// +/// let mut logger = BuildLog::new(std::io::stdout()) +/// .buildpack_name("Heroku Ruby Buildpack"); +/// +/// logger = logger +/// .section("Ruby version") +/// .step_timed("Installing") +/// .finish_timed_step() +/// .end_section(); +/// +/// logger.finish_logging(); +/// ``` +/// +/// To log inside of a layer see `section_log`. +/// +/// For usage details run `cargo run --bin print_style_guide` + +#[allow(clippy::module_name_repetitions)] +#[derive(Debug)] +pub struct BuildLog { + pub(crate) io: W, + pub(crate) data: BuildData, + pub(crate) state: PhantomData, +} + +/// A bag of data passed throughout the lifecycle of a `BuildLog` +#[derive(Debug)] +pub(crate) struct BuildData { + pub(crate) started: Instant, +} + +impl Default for BuildData { + fn default() -> Self { + Self { + started: Instant::now(), + } + } +} + +/// Various states for `BuildLog` to contain +/// +/// The `BuildLog` struct acts as a logging state machine. These structs +/// are meant to represent those states +pub(crate) mod state { + #[derive(Debug)] + pub struct NotStarted; + + #[derive(Debug)] + pub struct Started; + + #[derive(Debug)] + pub struct InSection; +} + +impl BuildLog +where + W: Write + Debug, +{ + pub fn new(io: W) -> Self { + Self { + io, + state: PhantomData::, + data: BuildData::default(), + } + } +} + +impl Logger for BuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + fn buildpack_name(mut self, buildpack_name: &str) -> Box { + write_now( + &mut self.io, + format!("{}\n\n", style::header(buildpack_name)), + ); + + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } + + fn without_buildpack_name(self) -> Box { + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } +} + +impl StartedLogger for BuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + fn section(mut self: Box, s: &str) -> Box { + writeln_now(&mut self.io, style::section(s)); + + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } + + fn finish_logging(mut self: Box) { + let elapsed = style::time::human(&self.data.started.elapsed()); + let details = style::details(format!("finished in {elapsed}")); + + writeln_now(&mut self.io, style::section(format!("Done {details}"))); + } + + fn announce(self: Box) -> Box>> { + Box::new(AnnounceBuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + leader: Some("\n".to_string()), + }) + } +} +impl SectionLogger for BuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + fn mut_step(&mut self, s: &str) { + writeln_now(&mut self.io, style::step(s)); + } + + fn step(mut self: Box, s: &str) -> Box { + self.mut_step(s); + + Box::new(BuildLog { + io: self.io, + state: PhantomData::, + data: self.data, + }) + } + + fn step_timed(self: Box, s: &str) -> Box { + let start = style::step(format!("{s}{}", style::background_timer_start())); + let tick = style::background_timer_tick(); + let end = style::background_timer_end(); + + let arc_io = Arc::new(Mutex::new(self.io)); + let background = start_timer(&arc_io, Duration::from_secs(1), start, tick, end); + + Box::new(FinishTimedStep { + arc_io, + background, + data: self.data, + }) + } + + fn step_timed_stream(mut self: Box, s: &str) -> Box { + self.mut_step(s); + + let started = Instant::now(); + let arc_io = Arc::new(Mutex::new(self.io)); + let mut stream = StreamTimed { + arc_io, + data: self.data, + started, + }; + stream.start(); + + Box::new(stream) + } + + fn end_section(self: Box) -> Box { + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } + + fn announce(self: Box) -> Box>> { + Box::new(AnnounceBuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + leader: Some("\n".to_string()), + }) + } +} + +// Store internal state, print leading character exactly once on warning or important +#[derive(Debug)] +struct AnnounceBuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + io: W, + data: BuildData, + state: PhantomData, + leader: Option, +} + +impl AnnounceBuildLog +where + T: Debug, + W: Write + Send + Sync + Debug + 'static, +{ + fn log_warning_shared(&mut self, s: &str) { + if let Some(leader) = self.leader.take() { + write_now(&mut self.io, leader); + } + + writeln_now(&mut self.io, style::warning(s.trim())); + writeln_now(&mut self.io, ""); + } + + fn log_important_shared(&mut self, s: &str) { + if let Some(leader) = self.leader.take() { + write_now(&mut self.io, leader); + } + writeln_now(&mut self.io, style::important(s.trim())); + writeln_now(&mut self.io, ""); + } + + fn log_warn_later_shared(&mut self, s: &str) { + let mut formatted = style::warning(s.trim()); + formatted.push('\n'); + + match crate::output::warn_later::try_push(formatted) { + Ok(()) => {} + Err(error) => { + eprintln!("[Buildpack Warning]: Cannot use the delayed warning feature due to error: {error}"); + self.log_warning_shared(s); + } + }; + } +} + +impl ErrorLogger for AnnounceBuildLog +where + T: Debug, + W: Write + Send + Sync + Debug + 'static, +{ + fn error(mut self: Box, s: &str) { + if let Some(leader) = self.leader.take() { + write_now(&mut self.io, leader); + } + writeln_now(&mut self.io, style::error(s.trim())); + writeln_now(&mut self.io, ""); + } +} + +impl AnnounceLogger for AnnounceBuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + type ReturnTo = Box; + + fn warning(mut self: Box, s: &str) -> Box> { + self.log_warning_shared(s); + + self + } + + fn warn_later( + mut self: Box, + s: &str, + ) -> Box> { + self.log_warn_later_shared(s); + + self + } + + fn important( + mut self: Box, + s: &str, + ) -> Box> { + self.log_important_shared(s); + + self + } + + fn end_announce(self: Box) -> Box { + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } +} + +impl AnnounceLogger for AnnounceBuildLog +where + W: Write + Send + Sync + Debug + 'static, +{ + type ReturnTo = Box; + + fn warning(mut self: Box, s: &str) -> Box> { + self.log_warning_shared(s); + self + } + + fn warn_later( + mut self: Box, + s: &str, + ) -> Box> { + self.log_warn_later_shared(s); + self + } + + fn important( + mut self: Box, + s: &str, + ) -> Box> { + self.log_important_shared(s); + self + } + + fn end_announce(self: Box) -> Box { + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } +} + +/// Implements Box +/// +/// Ensures that the `W` can be passed across thread boundries +/// by wrapping in a mutex. +/// +/// It implements writing by unlocking and delegating to the internal writer. +/// Can be used for `Box::io()` +#[derive(Debug)] +struct LockedWriter { + arc: Arc>, +} + +impl Write for LockedWriter +where + W: Write + Send + Sync + Debug + 'static, +{ + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut io = self.arc.lock().expect("Logging mutex poisoned"); + io.write(buf) + } + + fn flush(&mut self) -> std::io::Result<()> { + let mut io = self.arc.lock().expect("Logging mutex poisoned"); + io.flush() + } +} + +/// Used to implement `Box` interface +/// +/// Mostly used for logging a running command +#[derive(Debug)] +struct StreamTimed { + data: BuildData, + arc_io: Arc>, + started: Instant, +} + +impl StreamTimed +where + W: Write + Send + Sync + Debug, +{ + fn start(&mut self) { + let mut guard = self.arc_io.lock().expect("Logging mutex posioned"); + let mut io = guard.by_ref(); + // Newline before stream + writeln_now(&mut io, ""); + } +} + +// Need a trait that is both write a debug +trait WriteDebug: Write + Debug {} +impl WriteDebug for T where T: Write + Debug {} + +/// Attempt to unwrap an io inside of an `Arc` if this fails because there is more +/// than a single reference don't panic, return the original IO instead. +/// +/// This prevents a runtime panic and allows us to continue logging +fn try_unwrap_arc_io(arc_io: Arc>) -> Box +where + W: Write + Send + Sync + Debug + 'static, +{ + match Arc::try_unwrap(arc_io) { + Ok(mutex) => Box::new(mutex.into_inner().expect("Logging mutex was poisioned")), + Err(original) => Box::new(LockedWriter { arc: original }), + } +} + +impl StreamLogger for StreamTimed +where + W: Write + Send + Sync + Debug + 'static, +{ + /// Yield boxed writer that can be used for formatting and streaming contents + /// back to the logger. + fn io(&mut self) -> Box { + Box::new(crate::write::line_mapped( + LockedWriter { + arc: self.arc_io.clone(), + }, + style::cmd_stream_format, + )) + } + + fn finish_timed_stream(self: Box) -> Box { + let duration = self.started.elapsed(); + let mut io = try_unwrap_arc_io(self.arc_io); + + // // Newline after stream + writeln_now(&mut io, ""); + + let mut section = BuildLog { + io, + data: self.data, + state: PhantomData::, + }; + + section.mut_step(&format!( + "Done {}", + style::details(style::time::human(&duration)) + )); + + Box::new(section) + } +} + +/// Implements `Box` +/// +/// Used to end a background inline timer i.e. Installing ...... (<0.1s) +#[derive(Debug)] +struct FinishTimedStep { + data: BuildData, + arc_io: Arc>, + background: StopJoinGuard, +} + +impl TimedStepLogger for FinishTimedStep +where + W: Write + Send + Sync + Debug + 'static, +{ + fn finish_timed_step(self: Box) -> Box { + // Must stop background writing thread before retrieving IO + let duration = self.background.stop().elapsed(); + let mut io = try_unwrap_arc_io(self.arc_io); + + writeln_now(&mut io, style::details(style::time::human(&duration))); + + Box::new(BuildLog { + io, + data: self.data, + state: PhantomData::, + }) + } +} + +/// Internal helper, ensures that all contents are always flushed (never buffered) +/// +/// This is especially important for writing individual characters to the same line +fn write_now(destination: &mut D, msg: impl AsRef) { + write!(destination, "{}", msg.as_ref()).expect("Logging error: UI writer closed"); + + destination + .flush() + .expect("Logging error: UI writer closed"); +} + +/// Internal helper, ensures that all contents are always flushed (never buffered) +fn writeln_now(destination: &mut D, msg: impl AsRef) { + writeln!(destination, "{}", msg.as_ref()).expect("Logging error: UI writer closed"); + + destination + .flush() + .expect("Logging error: UI writer closed"); +} + +#[cfg(test)] +mod test { + use super::*; + use crate::command::CommandExt; + use crate::output::style::{self, strip_control_codes}; + use crate::output::util::{strip_trailing_whitespace, ReadYourWrite}; + use crate::output::warn_later::WarnGuard; + use indoc::formatdoc; + use libcnb_test::assert_contains; + use pretty_assertions::assert_eq; + + #[test] + fn test_captures() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + let mut stream = BuildLog::new(writer) + .buildpack_name("Heroku Ruby Buildpack") + .section("Ruby version `3.1.3` from `Gemfile.lock`") + .step_timed("Installing") + .finish_timed_step() + .end_section() + .section("Hello world") + .step_timed_stream("Streaming stuff"); + + let value = "stuff".to_string(); + writeln!(stream.io(), "{value}").unwrap(); + + stream.finish_timed_stream().end_section().finish_logging(); + + let expected = formatdoc! {" + + # Heroku Ruby Buildpack + + - Ruby version `3.1.3` from `Gemfile.lock` + - Installing ... (< 0.1s) + - Hello world + - Streaming stuff + + stuff + + - Done (< 0.1s) + - Done (finished in < 0.1s) + "}; + + assert_eq!( + expected, + strip_trailing_whitespace(style::strip_control_codes(reader.read_lossy().unwrap())) + ); + } + + #[test] + fn test_streaming_a_command() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + let mut stream = BuildLog::new(writer) + .buildpack_name("Streaming buildpack demo") + .section("Command streaming") + .step_timed_stream("Streaming stuff"); + + std::process::Command::new("echo") + .arg("hello world") + .output_and_write_streams(stream.io(), stream.io()) + .unwrap(); + + stream.finish_timed_stream().end_section().finish_logging(); + + let actual = + strip_trailing_whitespace(style::strip_control_codes(reader.read_lossy().unwrap())); + + assert_contains!(actual, " hello world\n"); + } + + #[test] + fn warning_step_padding() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + BuildLog::new(writer) + .buildpack_name("RCT") + .section("Guest thoughs") + .step("The scenery here is wonderful") + .announce() + .warning("It's too crowded here\nI'm tired") + .end_announce() + .step("The jumping fountains are great") + .step("The music is nice here") + .end_section() + .finish_logging(); + + let expected = formatdoc! {" + + # RCT + + - Guest thoughs + - The scenery here is wonderful + + ! It's too crowded here + ! I'm tired + + - The jumping fountains are great + - The music is nice here + - Done (finished in < 0.1s) + "}; + + assert_eq!(expected, strip_control_codes(reader.read_lossy().unwrap())); + } + + #[test] + fn double_warning_step_padding() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + let logger = BuildLog::new(writer) + .buildpack_name("RCT") + .section("Guest thoughs") + .step("The scenery here is wonderful") + .announce(); + + logger + .warning("It's too crowded here") + .warning("I'm tired") + .end_announce() + .step("The jumping fountains are great") + .step("The music is nice here") + .end_section() + .finish_logging(); + + let expected = formatdoc! {" + + # RCT + + - Guest thoughs + - The scenery here is wonderful + + ! It's too crowded here + + ! I'm tired + + - The jumping fountains are great + - The music is nice here + - Done (finished in < 0.1s) + "}; + + assert_eq!(expected, strip_control_codes(reader.read_lossy().unwrap())); + } + + #[test] + fn warn_later_doesnt_output_newline() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + let warn_later = WarnGuard::new(writer.clone()); + BuildLog::new(writer) + .buildpack_name("Walkin' on the Sun") + .section("So don't delay, act now, supplies are running out") + .step("Allow if you're still alive, six to eight years to arrive") + .step("And if you follow, there may be a tomorrow") + .announce() + .warn_later("And all that glitters is gold") + .warn_later("Only shooting stars break the mold") + .end_announce() + .step("But if the offer's shunned") + .step("You might as well be walking on the Sun") + .end_section() + .finish_logging(); + + drop(warn_later); + + let expected = formatdoc! {" + + # Walkin' on the Sun + + - So don't delay, act now, supplies are running out + - Allow if you're still alive, six to eight years to arrive + - And if you follow, there may be a tomorrow + - But if the offer's shunned + - You might as well be walking on the Sun + - Done (finished in < 0.1s) + + ! And all that glitters is gold + + ! Only shooting stars break the mold + "}; + + assert_eq!(expected, strip_control_codes(reader.read_lossy().unwrap())); + } + + #[test] + fn announce_and_exit_makes_no_whitespace() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + + BuildLog::new(writer) + .buildpack_name("Quick and simple") + .section("Start") + .step("Step") + .announce() // <== Here + .end_announce() // <== Here + .end_section() + .finish_logging(); + + let expected = formatdoc! {" + + # Quick and simple + + - Start + - Step + - Done (finished in < 0.1s) + "}; + + assert_eq!(expected, strip_control_codes(reader.read_lossy().unwrap())); + } +} diff --git a/libherokubuildpack/src/output/interface.rs b/libherokubuildpack/src/output/interface.rs new file mode 100644 index 00000000..46dc615b --- /dev/null +++ b/libherokubuildpack/src/output/interface.rs @@ -0,0 +1,54 @@ +use std::fmt::Debug; +use std::io::Write; + +/// Consuming stateful logger interface +/// +/// The log pattern used by `BuildLog` is a consuming state machine that is designed to minimize +/// the amount of mistakes that can result in malformed build output. +/// +/// The interface isn't stable and may need to change. + +pub trait Logger: Debug { + fn buildpack_name(self, s: &str) -> Box; + fn without_buildpack_name(self) -> Box; +} + +pub trait StartedLogger: Debug { + fn section(self: Box, s: &str) -> Box; + fn finish_logging(self: Box); + + fn announce(self: Box) -> Box>>; +} + +pub trait SectionLogger: Debug { + fn step(self: Box, s: &str) -> Box; + fn mut_step(&mut self, s: &str); + fn step_timed(self: Box, s: &str) -> Box; + fn step_timed_stream(self: Box, s: &str) -> Box; + fn end_section(self: Box) -> Box; + + fn announce(self: Box) -> Box>>; +} + +pub trait AnnounceLogger: ErrorLogger + Debug { + type ReturnTo; + + fn warning(self: Box, s: &str) -> Box>; + fn warn_later(self: Box, s: &str) -> Box>; + fn important(self: Box, s: &str) -> Box>; + + fn end_announce(self: Box) -> Self::ReturnTo; +} + +pub trait TimedStepLogger: Debug { + fn finish_timed_step(self: Box) -> Box; +} + +pub trait StreamLogger: Debug { + fn io(&mut self) -> Box; + fn finish_timed_stream(self: Box) -> Box; +} + +pub trait ErrorLogger: Debug { + fn error(self: Box, s: &str); +} diff --git a/libherokubuildpack/src/output/mod.rs b/libherokubuildpack/src/output/mod.rs new file mode 100644 index 00000000..a862a9c9 --- /dev/null +++ b/libherokubuildpack/src/output/mod.rs @@ -0,0 +1,7 @@ +mod background_timer; +pub mod build_log; +pub mod interface; +pub mod section_log; +pub mod style; +mod util; +pub mod warn_later; diff --git a/libherokubuildpack/src/output/section_log.rs b/libherokubuildpack/src/output/section_log.rs new file mode 100644 index 00000000..c5781081 --- /dev/null +++ b/libherokubuildpack/src/output/section_log.rs @@ -0,0 +1,129 @@ +use crate::output::build_log::{state, BuildData, BuildLog}; +#[allow(clippy::wildcard_imports)] +pub use crate::output::interface::*; +use std::io::Stdout; +use std::marker::PhantomData; + +/// Write to the build output in a `Box` format with functions +/// +/// ## What +/// +/// Logging from within a layer can be difficult because calls to the layer interface are not +/// mutable nor consumable. Functions can be used at any time with no restrictions. The +/// only downside is that the buildpack author (you) is now responsible for: +/// +/// - Ensuring that `Box::section()` was called right before any of these +/// functions are called. +/// - Ensuring that you are not attempting to log while already logging i.e. calling `step()` within a +/// `step_timed()` call. +/// +/// For usage details run `cargo run --bin print_style_guide` +/// +/// ## Use +/// +/// The main use case is logging inside of a layer: +/// +/// ```no_run +/// use libherokubuildpack::output::section_log::log_step_timed; +/// +/// // fn create( +/// // &self, +/// // context: &libcnb::build::BuildContext, +/// // layer_path: &std::path::Path, +/// // ) -> Result< +/// // libcnb::layer::LayerResult, +/// // ::Error, +/// // > { +/// log_step_timed("Installing", || { +/// // Install logic here +/// todo!() +/// }) +/// // } +/// ``` + +/// Output a message as a single step, ideally a short message +/// +/// ``` +/// use libherokubuildpack::output::section_log::log_step; +/// +/// log_step("Clearing cache (ruby version changed)"); +/// ``` +pub fn log_step(s: impl AsRef) { + logger().step(s.as_ref()); +} + +/// Will print the input string followed by a background timer +/// that will emit to the UI until the passed in function ends +/// +/// ``` +/// use libherokubuildpack::output::section_log::log_step_timed; +/// +/// log_step_timed("Installing", || { +/// // Install logic here +/// }); +/// ``` +/// +/// Timing information will be output at the end of the step. +pub fn log_step_timed(s: impl AsRef, f: impl FnOnce() -> T) -> T { + let timer = logger().step_timed(s.as_ref()); + let out = f(); + timer.finish_timed_step(); + out +} + +/// Will print the input string and yield a `Box` that can be used to print +/// to the output. The main use case is running commands +/// +/// ```no_run +/// use fun_run::CommandWithName; +/// use libherokubuildpack::output::section_log::log_step_stream; +/// use libherokubuildpack::output::style; +/// +/// let mut cmd = std::process::Command::new("bundle"); +/// cmd.arg("install"); +/// +/// log_step_stream(format!("Running {}", style::command(cmd.name())), |stream| { +/// cmd.stream_output(stream.io(), stream.io()).unwrap() +/// }); +/// ``` +/// +/// Timing information will be output at the end of the step. +pub fn log_step_stream( + s: impl AsRef, + f: impl FnOnce(&mut Box) -> T, +) -> T { + let mut stream = logger().step_timed_stream(s.as_ref()); + let out = f(&mut stream); + stream.finish_timed_stream(); + out +} + +/// Print an error block to the output +pub fn log_error(s: impl AsRef) { + logger().announce().error(s.as_ref()); +} + +/// Print an warning block to the output +pub fn log_warning(s: impl AsRef) { + logger().announce().warning(s.as_ref()); +} + +/// Print an warning block to the output at a later time +pub fn log_warning_later(s: impl AsRef) { + logger().announce().warn_later(s.as_ref()); +} + +/// Print an important block to the output +pub fn log_important(s: impl AsRef) { + logger().announce().important(s.as_ref()); +} + +fn logger() -> Box { + Box::new(BuildLog:: { + io: std::io::stdout(), + // Be careful not to do anything that might access this state + // as it's ephemeral data (i.e. not passed in from the start of the build) + data: BuildData::default(), + state: PhantomData, + }) +} diff --git a/libherokubuildpack/src/output/style.rs b/libherokubuildpack/src/output/style.rs new file mode 100644 index 00000000..abe5c7a6 --- /dev/null +++ b/libherokubuildpack/src/output/style.rs @@ -0,0 +1,337 @@ +use crate::output::util::LinesWithEndings; +use const_format::formatcp; +use std::fmt::Write; + +/// Helpers for formatting and colorizing your output + +/// Decorated str for prefixing "Help:" +pub const HELP: &str = formatcp!("{IMPORTANT_COLOR}! HELP{RESET}"); + +/// Decorated str for prefixing "Debug info:" +pub const DEBUG_INFO: &str = formatcp!("{IMPORTANT_COLOR}Debug info{RESET}"); + +/// Decorate a URL for the build output +#[must_use] +pub fn url(contents: impl AsRef) -> String { + colorize(URL_COLOR, contents) +} + +/// Decorate the name of a command being run i.e. `bundle install` +#[must_use] +pub fn command(contents: impl AsRef) -> String { + value(colorize(COMMAND_COLOR, contents.as_ref())) +} + +/// Decorate an important value i.e. `2.3.4` +#[must_use] +pub fn value(contents: impl AsRef) -> String { + let contents = colorize(VALUE_COLOR, contents.as_ref()); + format!("`{contents}`") +} + +/// Decorate additional information at the end of a line +#[must_use] +pub fn details(contents: impl AsRef) -> String { + let contents = contents.as_ref(); + format!("({contents})") +} + +pub(crate) const RED: &str = "\x1B[0;31m"; +pub(crate) const YELLOW: &str = "\x1B[0;33m"; +pub(crate) const CYAN: &str = "\x1B[0;36m"; + +pub(crate) const BOLD_CYAN: &str = "\x1B[1;36m"; +pub(crate) const BOLD_PURPLE: &str = "\x1B[1;35m"; // magenta + +pub(crate) const DEFAULT_DIM: &str = "\x1B[2;1m"; // Default color but softer/less vibrant +pub(crate) const RESET: &str = "\x1B[0m"; + +#[cfg(test)] +pub(crate) const NOCOLOR: &str = "\x1B[1;39m"; // Differentiate between color clear and explicit no color https://github.com/heroku/buildpacks-ruby/pull/155#discussion_r1260029915 +pub(crate) const ALL_CODES: [&str; 7] = [ + RED, + YELLOW, + CYAN, + BOLD_CYAN, + BOLD_PURPLE, + DEFAULT_DIM, + RESET, +]; + +pub(crate) const HEROKU_COLOR: &str = BOLD_PURPLE; +pub(crate) const VALUE_COLOR: &str = YELLOW; +pub(crate) const COMMAND_COLOR: &str = BOLD_CYAN; +pub(crate) const URL_COLOR: &str = CYAN; +pub(crate) const IMPORTANT_COLOR: &str = CYAN; +pub(crate) const ERROR_COLOR: &str = RED; + +#[allow(dead_code)] +pub(crate) const WARNING_COLOR: &str = YELLOW; + +const SECTION_PREFIX: &str = "- "; +const STEP_PREFIX: &str = " - "; +const CMD_INDENT: &str = " "; + +/// Used with libherokubuildpack linemapped command output +/// +#[must_use] +pub(crate) fn cmd_stream_format(mut input: Vec) -> Vec { + let mut result: Vec = CMD_INDENT.into(); + result.append(&mut input); + result +} + +#[must_use] +pub(crate) fn background_timer_start() -> String { + colorize(DEFAULT_DIM, " .") +} + +#[must_use] +pub(crate) fn background_timer_tick() -> String { + colorize(DEFAULT_DIM, ".") +} + +#[must_use] +pub(crate) fn background_timer_end() -> String { + colorize(DEFAULT_DIM, ". ") +} + +#[must_use] +pub(crate) fn section(topic: impl AsRef) -> String { + prefix_indent(SECTION_PREFIX, topic) +} + +#[must_use] +pub(crate) fn step(contents: impl AsRef) -> String { + prefix_indent(STEP_PREFIX, contents) +} + +/// Used to decorate a buildpack +#[must_use] +pub(crate) fn header(contents: impl AsRef) -> String { + let contents = contents.as_ref(); + colorize(HEROKU_COLOR, format!("\n# {contents}")) +} + +// Prefix is expected to be a single line +// +// If contents is multi line then indent additional lines to align with the end of the prefix. +pub(crate) fn prefix_indent(prefix: impl AsRef, contents: impl AsRef) -> String { + let prefix = prefix.as_ref(); + let contents = contents.as_ref(); + let non_whitespace_re = regex::Regex::new("\\S").expect("Clippy"); + let clean_prefix = strip_control_codes(prefix); + + let indent_str = non_whitespace_re.replace_all(&clean_prefix, " "); // Preserve whitespace characters like tab and space, replace all characters with spaces + let lines = LinesWithEndings::from(contents).collect::>(); + + if let Some((first, rest)) = lines.split_first() { + format!( + "{prefix}{first}{}", + rest.iter().fold(String::new(), |mut output, line| { + let _ = write!(output, "{indent_str}{line}"); + output + }) + ) + } else { + prefix.to_string() + } +} + +#[must_use] +pub(crate) fn important(contents: impl AsRef) -> String { + colorize(IMPORTANT_COLOR, bangify(contents)) +} + +#[must_use] +pub(crate) fn warning(contents: impl AsRef) -> String { + colorize(WARNING_COLOR, bangify(contents)) +} + +#[must_use] +pub(crate) fn error(contents: impl AsRef) -> String { + colorize(ERROR_COLOR, bangify(contents)) +} + +/// Helper method that adds a bang i.e. `!` before strings +pub(crate) fn bangify(body: impl AsRef) -> String { + prepend_each_line("!", " ", body) +} + +// Ensures every line starts with `prepend` +pub(crate) fn prepend_each_line( + prepend: impl AsRef, + separator: impl AsRef, + contents: impl AsRef, +) -> String { + let body = contents.as_ref(); + let prepend = prepend.as_ref(); + let separator = separator.as_ref(); + + let lines = LinesWithEndings::from(body) + .map(|line| { + if line.trim().is_empty() { + format!("{prepend}{line}") + } else { + format!("{prepend}{separator}{line}") + } + }) + .collect::(); + lines +} + +/// Colorizes a body while preserving existing color/reset combinations and clearing before newlines +/// +/// Colors with newlines are a problem since the contents stream to git which prepends `remote:` before the `libcnb_test` +/// if we don't clear, then we will colorize output that isn't ours. +/// +/// Explicitly uncolored output is handled by treating `\x1b[1;39m` (NOCOLOR) as a distinct case from `\x1b[0m` +pub(crate) fn colorize(color: &str, body: impl AsRef) -> String { + body.as_ref() + .split('\n') + // If sub contents are colorized it will contain SUBCOLOR ... RESET. After the reset, + // ensure we change back to the current color + .map(|line| line.replace(RESET, &format!("{RESET}{color}"))) // Handles nested color + // Set the main color for each line and reset after so we don't colorize `remote:` by accident + .map(|line| format!("{color}{line}{RESET}")) + // The above logic causes redundant colors and resets, clean them up + .map(|line| line.replace(&format!("{RESET}{color}{RESET}"), RESET)) + .map(|line| line.replace(&format!("{color}{color}"), color)) // Reduce useless color + .collect::>() + .join("\n") +} + +pub(crate) fn strip_control_codes(contents: impl AsRef) -> String { + let mut contents = contents.as_ref().to_string(); + for code in ALL_CODES { + contents = contents.replace(code, ""); + } + contents +} + +#[cfg(test)] +mod test { + use super::*; + + #[test] + fn test_prefix_indent() { + assert_eq!("- hello", &prefix_indent("- ", "hello")); + assert_eq!("- hello\n world", &prefix_indent("- ", "hello\nworld")); + assert_eq!("- hello\n world\n", &prefix_indent("- ", "hello\nworld\n")); + let actual = prefix_indent(format!("- {RED}help:{RESET} "), "hello\nworld\n"); + assert_eq!( + &format!("- {RED}help:{RESET} hello\n world\n"), + &actual + ); + } + + #[test] + fn test_bangify() { + let actual = bangify("hello"); + assert_eq!("! hello", actual); + + let actual = bangify("\n"); + assert_eq!("!\n", actual); + } + + #[test] + fn handles_explicitly_removed_colors() { + let nested = colorize(NOCOLOR, "nested"); + + let out = colorize(RED, format!("hello {nested} color")); + let expected = format!("{RED}hello {NOCOLOR}nested{RESET}{RED} color{RESET}"); + + assert_eq!(expected, out); + } + + #[test] + fn handles_nested_colors() { + let nested = colorize(CYAN, "nested"); + + let out = colorize(RED, format!("hello {nested} color")); + let expected = format!("{RED}hello {CYAN}nested{RESET}{RED} color{RESET}"); + + assert_eq!(expected, out); + } + + #[test] + fn splits_newlines() { + let actual = colorize(RED, "hello\nworld"); + let expected = format!("{RED}hello{RESET}\n{RED}world{RESET}"); + + assert_eq!(expected, actual); + } + + #[test] + fn simple_case() { + let actual = colorize(RED, "hello world"); + assert_eq!(format!("{RED}hello world{RESET}"), actual); + } +} + +pub(crate) mod time { + use std::time::Duration; + + // Returns the part of a duration only in miliseconds + pub(crate) fn milliseconds(duration: &Duration) -> u32 { + duration.subsec_millis() + } + + pub(crate) fn seconds(duration: &Duration) -> u64 { + duration.as_secs() % 60 + } + + pub(crate) fn minutes(duration: &Duration) -> u64 { + (duration.as_secs() / 60) % 60 + } + + pub(crate) fn hours(duration: &Duration) -> u64 { + (duration.as_secs() / 3600) % 60 + } + + #[must_use] + pub(crate) fn human(duration: &Duration) -> String { + let hours = hours(duration); + let minutes = minutes(duration); + let seconds = seconds(duration); + let miliseconds = milliseconds(duration); + + if hours > 0 { + format!("{hours}h {minutes}m {seconds}s") + } else if minutes > 0 { + format!("{minutes}m {seconds}s") + } else if seconds > 0 || miliseconds > 100 { + // 0.1 + format!("{seconds}.{miliseconds:0>3}s") + } else { + String::from("< 0.1s") + } + } + + #[cfg(test)] + mod test { + use super::*; + + #[test] + fn test_millis_and_seconds() { + let duration = Duration::from_millis(1024); + assert_eq!(24, milliseconds(&duration)); + assert_eq!(1, seconds(&duration)); + } + + #[test] + fn test_display_duration() { + let duration = Duration::from_millis(99); + assert_eq!("< 0.1s", human(&duration).as_str()); + + let duration = Duration::from_millis(1024); + assert_eq!("1.024s", human(&duration).as_str()); + + let duration = std::time::Duration::from_millis(60 * 1024); + assert_eq!("1m 1s", human(&duration).as_str()); + + let duration = std::time::Duration::from_millis(3600 * 1024); + assert_eq!("1h 1m 26s", human(&duration).as_str()); + } + } +} diff --git a/libherokubuildpack/src/output/util.rs b/libherokubuildpack/src/output/util.rs new file mode 100644 index 00000000..8b49fa6b --- /dev/null +++ b/libherokubuildpack/src/output/util.rs @@ -0,0 +1,186 @@ +use lazy_static::lazy_static; +use std::fmt::Debug; +use std::io::Write; +use std::ops::Deref; +use std::sync::{Arc, Mutex, MutexGuard, PoisonError}; + +lazy_static! { + static ref TRAILING_WHITESPACE_RE: regex::Regex = regex::Regex::new(r"\s+$").expect("clippy"); +} + +/// Threadsafe writer that can be read from +/// +/// Useful for testing +#[derive(Debug)] +pub(crate) struct ReadYourWrite +where + W: Write + AsRef<[u8]>, +{ + arc: Arc>, +} + +impl Clone for ReadYourWrite +where + W: Write + AsRef<[u8]> + Debug, +{ + fn clone(&self) -> Self { + Self { + arc: self.arc.clone(), + } + } +} + +impl Write for ReadYourWrite +where + W: Write + AsRef<[u8]> + Debug, +{ + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut writer = self.arc.lock().expect("Internal error"); + writer.write(buf) + } + + fn flush(&mut self) -> std::io::Result<()> { + let mut writer = self.arc.lock().expect("Internal error"); + writer.flush() + } +} + +impl ReadYourWrite +where + W: Write + AsRef<[u8]>, +{ + #[allow(dead_code)] + pub(crate) fn writer(writer: W) -> Self { + Self { + arc: Arc::new(Mutex::new(writer)), + } + } + + #[must_use] + #[allow(dead_code)] + pub(crate) fn reader(&self) -> Reader { + Reader { + arc: self.arc.clone(), + } + } + + #[must_use] + #[allow(dead_code)] + pub(crate) fn arc_io(&self) -> Arc> { + self.arc.clone() + } +} + +pub(crate) struct Reader +where + W: Write + AsRef<[u8]>, +{ + arc: Arc>, +} + +impl Reader +where + W: Write + AsRef<[u8]>, +{ + #[allow(dead_code)] + pub(crate) fn read_lossy(&self) -> Result>> { + let io = &self.arc.lock()?; + + Ok(String::from_utf8_lossy(io.as_ref()).to_string()) + } +} + +impl Deref for Reader +where + W: Write + AsRef<[u8]>, +{ + type Target = Arc>; + + fn deref(&self) -> &Self::Target { + &self.arc + } +} + +/// Iterator yielding every line in a string. The line includes newline character(s). +/// +/// +/// +/// The problem this solves is when iterating over lines of a string, the whitespace may be significant. +/// For example if you want to split a string and then get the original string back then calling +/// `lines().collect>().join("\n")` will never preserve trailing newlines. +/// +/// There's another option to `lines().fold(String::new(), |s, l| s + l + "\n")`, but that +/// always adds a trailing newline even if the original string doesn't have one. +pub(crate) struct LinesWithEndings<'a> { + input: &'a str, +} + +impl<'a> LinesWithEndings<'a> { + pub fn from(input: &'a str) -> LinesWithEndings<'a> { + LinesWithEndings { input } + } +} + +impl<'a> Iterator for LinesWithEndings<'a> { + type Item = &'a str; + + #[inline] + fn next(&mut self) -> Option<&'a str> { + if self.input.is_empty() { + return None; + } + let split = self.input.find('\n').map_or(self.input.len(), |i| i + 1); + + let (line, rest) = self.input.split_at(split); + self.input = rest; + Some(line) + } +} + +/// Removes trailing whitespace from lines +/// +/// Useful because most editors strip trailing whitespace (in test fixtures) +/// but commands emit newlines +/// with leading spaces. These can be sanatized by removing trailing whitespace. +#[allow(dead_code)] +pub(crate) fn strip_trailing_whitespace(s: impl AsRef) -> String { + LinesWithEndings::from(s.as_ref()) + .map(|line| { + // Remove empty indented lines + TRAILING_WHITESPACE_RE.replace(line, "\n").to_string() + }) + .collect::() +} + +#[cfg(test)] +mod test { + use super::*; + use std::fmt::Write; + + #[test] + fn test_trailing_whitespace() { + let actual = strip_trailing_whitespace("hello \n"); + assert_eq!("hello\n", &actual); + + let actual = strip_trailing_whitespace("hello\n \nworld\n"); + assert_eq!("hello\n\nworld\n", &actual); + } + + #[test] + fn test_lines_with_endings() { + let actual = LinesWithEndings::from("foo\nbar").fold(String::new(), |mut output, line| { + let _ = write!(output, "z{line}"); + output + }); + + assert_eq!("zfoo\nzbar", actual); + + let actual = + LinesWithEndings::from("foo\nbar\n").fold(String::new(), |mut output, line| { + let _ = write!(output, "z{line}"); + output + }); + + assert_eq!("zfoo\nzbar\n", actual); + } +} diff --git a/libherokubuildpack/src/output/warn_later.rs b/libherokubuildpack/src/output/warn_later.rs new file mode 100644 index 00000000..87395ac6 --- /dev/null +++ b/libherokubuildpack/src/output/warn_later.rs @@ -0,0 +1,347 @@ +use std::cell::RefCell; +use std::fmt::{Debug, Display}; +use std::io::Write; +use std::marker::PhantomData; +use std::rc::Rc; +use std::thread::ThreadId; + +pub type PhantomUnsync = PhantomData>; + +thread_local!(static WARN_LATER: RefCell>> = RefCell::new(None)); + +/// Queue a warning for later +/// +/// Build logs can be quite large and people don't always scroll back up to read every line. Delaying +/// a warning and emitting it right before the end of the build can increase the chances the app +/// developer will read it. +/// +/// ## Use - Setup a `WarnGuard` in your buildpack +/// +/// To ensure warnings are printed, even in the event of errors, you must create a `WarnGuard` +/// in your buildpack that will print any delayed warnings when dropped: +/// +/// ```no_run +/// // src/main.rs +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// +/// // fn build(&self, context: BuildContext) -> libcnb::Result { +/// let warn_later = WarnGuard::new(std::io::stdout()); +/// // ... +/// +/// // Warnings will be emitted when the warn guard is dropped +/// drop(warn_later); +/// // } +/// ``` +/// +/// Alternatively you can manually print delayed warnings: +/// +/// ```no_run +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// +/// // fn build(&self, context: BuildContext) -> libcnb::Result { +/// let warn_later = WarnGuard::new(std::io::stdout()); +/// // ... +/// +/// // Consumes the guard, prints and clears any delayed warnings. +/// warn_later.warn_now(); +/// // } +/// ``` +/// +/// ## Use - Issue a delayed warning +/// +/// Once a warn guard is in place you can queue a warning using `section_log::log_warning_later` or `build_log::*`: +/// +/// ``` +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// use libherokubuildpack::output::build_log::*; +/// +/// // src/main.rs +/// let warn_later = WarnGuard::new(std::io::stdout()); +/// +/// BuildLog::new(std::io::stdout()) +/// .buildpack_name("Julius Caesar") +/// .announce() +/// .warn_later("Beware the ides of march"); +/// ``` +/// +/// ``` +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// use libherokubuildpack::output::section_log::log_warning_later; +/// +/// // src/main.rs +/// let warn_later = WarnGuard::new(std::io::stdout()); +/// +/// // src/layers/greenday.rs +/// log_warning_later("WARNING: Live without warning"); +/// ``` + +/// Pushes a string to a thread local warning vec for to be emitted later +/// +/// # Errors +/// +/// If the internal `WARN_LATER` option is `None` this will emit a `WarnLaterError` because +/// the function call might not be visible to the application owner using the buildpack. +/// +/// This state can happen if no `WarnGuard` is created in the thread where the delayed warning +/// message is trying to be pushed. It can also happen if multiple `WarnGuard`-s are created in the +/// same thread and one of them "takes" the contents before the others go out of scope. +/// +/// For best practice create one and only one `WarnGuard` per thread at a time to avoid this error +/// state. +pub(crate) fn try_push(s: impl AsRef) -> Result<(), WarnLaterError> { + WARN_LATER.with(|cell| match &mut *cell.borrow_mut() { + Some(warnings) => { + warnings.push(s.as_ref().to_string()); + Ok(()) + } + None => Err(WarnLaterError::MissingGuardForThread( + std::thread::current().id(), + )), + }) +} + +/// Ensures a warning vec is present and pushes to it +/// +/// Should only ever be used within a `WarnGuard`. +/// +/// The state where the warnings are taken, but a warn guard is still present +/// can happen when more than one warn guard is created in the same thread +fn force_push(s: impl AsRef) { + WARN_LATER.with(|cell| { + let option = &mut *cell.borrow_mut(); + option + .get_or_insert(Vec::new()) + .push(s.as_ref().to_string()); + }); +} + +/// Removes all delayed warnings from current thread +/// +/// Should only execute from within a `WarnGuard` +fn take() -> Option> { + WARN_LATER.with(|cell| cell.replace(None)) +} + +#[allow(clippy::module_name_repetitions)] +#[derive(Debug)] +pub enum WarnLaterError { + MissingGuardForThread(ThreadId), +} + +impl Display for WarnLaterError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + WarnLaterError::MissingGuardForThread(id) => { + writeln!( + f, + "Cannot use warn_later unless a WarnGuard has been created\n and not yet dropped in the current thread: {id:?}", + ) + } + } + } +} + +/// Delayed Warning emitter +/// +/// To use the delayed warnings feature you'll need to first register a guard. +/// This guard will emit warnings when it goes out of scope or when you manually force it +/// to emit warnings. +/// +/// This struct allows delayed warnings to be emitted even in the even there's an error. +/// +/// See the `warn_later` module docs for usage instructions. +/// +/// The internal design of this features relies on state tied to the current thread. +/// As a result, this struct is not send or sync: +/// +/// ```compile_fail +/// // Fails to compile +/// # // Do not remove this test, it is the only thing that asserts this is not sync +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// +/// fn is_sync(t: impl Sync) {} +/// +/// is_sync(WarnGuard::new(std::io::stdout())) +/// ``` +/// +/// ```compile_fail +/// // Fails to compile +/// # // Do not remove this test, it is the only thing that asserts this is not send +/// use libherokubuildpack::output::warn_later::WarnGuard; +/// +/// fn is_send(t: impl Send) {} +/// +/// is_send(WarnGuard::new(std::io::stdout())) +/// ``` +/// +/// If you are warning in multiple threads you can pass queued warnings from one thread to another. +/// +/// ```rust +/// use libherokubuildpack::output::warn_later::{WarnGuard, DelayedWarnings}; +/// +/// let main_guard = WarnGuard::new(std::io::stdout()); +/// +/// let (delayed_send, delayed_recv) = std::sync::mpsc::channel::(); +/// +/// std::thread::spawn(move || { +/// let sub_guard = WarnGuard::new(std::io::stdout()); +/// // ... +/// delayed_send +/// .send(sub_guard.consume_quiet()) +/// .unwrap(); +/// }) +/// .join(); +/// +/// main_guard +/// .extend_warnings(delayed_recv.recv().unwrap()); +/// ``` +#[derive(Debug)] +pub struct WarnGuard +where + W: Write + Debug, +{ + // Private inner to force public construction through `new()` which tracks creation state per thread. + io: W, + /// The use of WarnGuard is directly tied to the thread where it was created + /// This forces the struct to not be send or sync + /// + /// To move warn later data between threads, drain quietly, send the data to another + /// thread, and re-apply those warnings to a WarnGuard in the other thread. + unsync: PhantomUnsync, +} + +impl WarnGuard +where + W: Write + Debug, +{ + #[must_use] + #[allow(clippy::new_without_default)] + pub fn new(io: W) -> Self { + WARN_LATER.with(|cell| { + let maybe_warnings = &mut *cell.borrow_mut(); + if let Some(warnings) = maybe_warnings.take() { + let _ = maybe_warnings.insert(warnings); + eprintln!("[Buildpack warning]: Multiple `WarnGuard`-s in thread {id:?}, this may cause unexpected delayed warning output", id = std::thread::current().id()); + } else { + let _ = maybe_warnings.insert(Vec::new()); + } + }); + + Self { + io, + unsync: PhantomData, + } + } + + /// Use to move warnings from a different thread into this one + pub fn extend_warnings(&self, warnings: DelayedWarnings) { + for warning in warnings.inner { + force_push(warning.clone()); + } + } + + /// Use to move warnings out of the current thread without emitting to the UI. + pub fn consume_quiet(self) -> DelayedWarnings { + DelayedWarnings { + inner: take().unwrap_or_default(), + } + } + + /// Consumes self, prints and drains all existing delayed warnings + pub fn warn_now(self) { + drop(self); + } +} + +impl Drop for WarnGuard +where + W: Write + Debug, +{ + fn drop(&mut self) { + if let Some(warnings) = take() { + if !warnings.is_empty() { + for warning in &warnings { + writeln!(&mut self.io).expect("warn guard IO is writeable"); + write!(&mut self.io, "{warning}").expect("warn guard IO is writeable"); + } + } + } + } +} + +/// Holds warnings from a consumed `WarnGuard` +/// +/// The intended use of this struct is to pass warnings from one `WarnGuard` to another. +#[derive(Debug)] +pub struct DelayedWarnings { + // Private inner, must be constructed within a WarnGuard + inner: Vec, +} + +#[cfg(test)] +mod test { + use super::*; + use crate::output::util::ReadYourWrite; + use libcnb_test::assert_contains; + + #[test] + fn test_warn_guard_registers_itself() { + // Err when a guard is not yet created + assert!(try_push("lol").is_err()); + + // Don't err when a guard is created + let _warn_guard = WarnGuard::new(Vec::new()); + try_push("lol").unwrap(); + } + + #[test] + fn test_logging_a_warning() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let warn_guard = WarnGuard::new(writer); + drop(warn_guard); + + assert_eq!(String::new(), reader.read_lossy().unwrap()); + + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let warn_guard = WarnGuard::new(writer); + let message = + "Possessing knowledge and performing an action are two entirely different processes"; + + try_push(message).unwrap(); + drop(warn_guard); + + assert_contains!(reader.read_lossy().unwrap(), message); + + // Assert empty after calling drain + assert!(take().is_none()); + } + + #[test] + fn test_delayed_warnings_on_drop() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let guard = WarnGuard::new(writer); + + let message = "You don't have to have a reason to be tired. You don't have to earn rest or comfort. You're allowed to just be."; + try_push(message).unwrap(); + drop(guard); + + assert_contains!(reader.read_lossy().unwrap(), message); + } + + #[test] + fn does_not_double_whitespace() { + let writer = ReadYourWrite::writer(Vec::new()); + let reader = writer.reader(); + let guard = WarnGuard::new(writer); + + let message = "Caution: This test is hot\n"; + try_push(message).unwrap(); + drop(guard); + + let expected = "\nCaution: This test is hot\n".to_string(); + assert_eq!(expected, reader.read_lossy().unwrap()); + } +}