From 6d4029f1cea8044ad95b9a0c16b1b961fb89ade0 Mon Sep 17 00:00:00 2001 From: Richard Schneeman Date: Mon, 30 Oct 2023 10:11:03 -0500 Subject: [PATCH] Update the logging interface (#198) * WIP * Threaded printing with internal writer passing works I ran into some move issues and I'm not incredibly comfortable with multithreading and the memory rules. I leaned on this post https://users.rust-lang.org/t/take-ownership-of-arc-mutex-t-inner-value/38097/2 which helped me get values back out of the mutex. There's a very high number of expect/unwraps in this code. Also the addition of NullWriter to get it to compile feels wrong (as it puts our program in an invalid state (cannot print if we try, but it doesn't error). For ergonomics all these expectations make the end API better. IDK if it's good enough to have this code tested and keep them in or if this really needs to return a Result. If we did return a result I don't know that there's a case where the buildpack author could safely continue as they will have lost access to their writer struct (since any errors here effectively mean we cannot get our destination again). * WIP scoped thread experiment * WIP non-scopped-background logger * Implement Stop timer on drop * WIP cannot get data back out * Introduce BuildLog All tests passing, happy with this implementation but still needs cleanup. * Cleanup Still need: - Implement the three ways to run a command - Add build logs via new interface - Implement formatting - More cleanup * Test using memory instead of files Previously I was stuck trying to get the contents written by the BuildLog as trait objects only expose methods implemented by the trait and I didn't want to add a `read(&self)` method because not all `T: Write` can be read. I was trying to downcast it to a concrete struct and couldn't get that to work. Eventually I realized that a `File` is `Write` and can be read even when the `File` struct is consumed as I'll have a separate reference to a path on disk. That worked well but still didn't feel like the correct long term solution. Another alternative I've considered is making the BuildLog take a `Arc>` but this didn't feel right as it was essentially a feature only for testing (i.e. Test Induced Damage). Using a blend of the File strategy and the desire to have multiple references to the writer I realized that if I made my own struct and implemented `Write` on that, it could hold an `Arc>` without BuildLog ever needing to know that interior state was being shared. With that in mind I wrote `ReadYourWrite` which implements `Write`, takes a `T: Write` and allows you to easily get a clone of `Arc>`. I added an additional trait bounds that says anything that goes into ReaderWriter needs to be able to be converted into a slice of bytes which can then be turned into a string. Maybe there's a better trait bounds, but that one satisfies my needs. * Expose streaming io in BuildLog Previously there was a desire to log running commands. I still want to do that, but I struggled with an interface that I liked. This approach instead gives us a set of building blocks that a command runner could then use, rather than forcing our logger to know about running commands. * Fun run interfaces Largely taken from https://github.com/heroku/buildpacks-ruby/blob/4494e98d01c3874d194cc2f8789aa577c4fd0a05/commons/src/fun_run.rs * Introduce CommandWithName trait Gives us a really nice interface for the whole command execution flow: defining a command, giving it a name and then running it (while preserving the name). * Expose output interface * WIP layer logging Strategy here is interior mutability. It works but isn't elegant. * Debuggable logger * WIP Layer logging without lifetime * Layer logger cleaned up * Bundle download layer moved to new output interface * Bundle install layer moved to new output interface * Gem list and default processesmoved to new output interface * Take tasks logging moved to new output interface * Delete old build logging module TODO - Update errors to match fork - Output errors on CI run - Run ruby getting started guide on CI * Match error text to prior work In https://github.com/heroku/buildpacks-ruby/blob/4494e98d01c3874d194cc2f8789aa577c4fd0a05/buildpacks/ruby/src/user_errors.rs we updated error messages. I've matched that relatively closely and annotated other features that are missing from the error output. Notably missing are diagnostics and formatting the errors we collect. We also don't have a mechanism to print the existing errors on CI runs as in that branch. * Address clippy complaints and move LayerLogger New clippy complaints, specifically complaining about panics. I have some interfaces that are actually safe to use, but possibly unsafe within. I made them safer by hiding that interior state more. I moved that code in LayerLogger to its own module as it's already quite complex. I moved ReadyYourWrite to a general module and I want to move all things that aren't BuildLog out of log.rs. Also revisit naming later. Some clippy violations still exist due to placeholder code for the errors and one due to me knowing I'm going to revisit/re-write code on Monday with Manuel: ``` warning: usage of an `Arc` that is not `Send` or `Sync` --> commons/src/output/layer_logger.rs:112:20 | 112 | inner: Arc::new(Mutex::new(SectionLoggerCell::new(logger))), | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ | = note: the trait `Send` is not implemented for `Mutex` = note: the trait `Sync` is not implemented for `Mutex` = note: required for `Arc>` to implement `Send` and `Sync` = help: consider using an `Rc` instead or wrapping the inner type with a `Mutex` = help: for further information visit https://rust-lang.github.io/rust-clippy/master/index.html#arc_with_non_send_sync = note: `#[warn(clippy::arc_with_non_send_sync)]` on by default ``` * Preserve long command for debugging Previously when the command errored the message would only show `gem install bundler --version ` however that could lead to weird error messages. For example if `--install-dir` is removed as an argument to the command the message would make no sense. This change preserves the full command in the case of errors but shows the short command for inline installation. * Add `ls -la` diagnostics to missing Gemfile.lock * Align multiline step and section contents No: ``` - I am the very model of a modern Major-Gineral, I've information vegetable, animal, and mineral, I know the kings of England, and I quote the fights historical From Marathon to Waterloo, in order categorical; I'm very well acquainted, too, with matters mathematical, I understand equations, both the simple and quadratical, About binomial theorem I'm teeming with a lot o' news, With many cheerful facts about the square of the hypotenuse. ``` Yes ``` - I am the very model of a modern Major-Gineral, I've information vegetable, animal, and mineral, I know the kings of England, and I quote the fights historical From Marathon to Waterloo, in order categorical; I'm very well acquainted, too, with matters mathematical, I understand equations, both the simple and quadratical, About binomial theorem I'm teeming with a lot o' news, With many cheerful facts about the square of the hypotenuse. ``` * Fix outstanding error formatting TODOs * Introduce living style guide TODO: Warnings and errors look off based on whitespace before/after the block. This is a symptom of not knowing that came before. I think we can fix this by introducing an AnnounceLogger that must be used to gain access to error/warning/important. TODO: The `step_and` should really be `step` while the current `step` should be `step_mut`. TODO: Make error, warning, important chainable. * Handle control characters when indenting with a prefix * Make SectionLogger.step chainable Moves step to `mut_step` and `step_and` to `step`. * Clippy * Expose function only section logging interface Solves the same problem as LayerLogger without runtime panics. It means that the developer must manually make sure they're inside of a `SectionLogger` instance and that it's the same logging style. This can be aided by types. In this example I'm requiring the layer is constructed with an `&a dyn SectionLogger`. This is annotation is optional as it introduces an extra unnecessary lifetime to the layer struct. * Remove LayerLogger in favor of section_log mod * Inject metadata for all layers Reduce dynamic logic inside of layers by pre-generating metadata and passing it in. When we do this we can reduce reliance on context as well as reducing other values that need to be passed in. * Print style guide on CI runs * Clippy, CI, and CHANGELOG * Clean up module visibility * Move panic into tested unit code path * Introduce fat::HELP and fat::DEBUG_INFO constants It's easier to work with and makes more sense. I tried using lazy_static and the `colorize` function, but for some reason it told me that my constant didn't implement display. Possibly a static that is `&'static str` is considered a thing that is different than a const `&'static str` but possibly I did something weird in the implementation. Add docs for these as well as `section_log` in the `print_style_guide` * Add docs and rearrange code * Reduce timing effects from tests Separating out running a command from validating the streaming interface formatting. This is needed because some times it takes a split second longer to execute a command based on CPU load: ``` left: `" - Done (finished in < 0.1s) "`, right: `" - Done (finished in 0.273s) "`', commons/src/output/log.rs:392:9 ``` * Clippy * Docs * Remove panic when joining logger When returning a StreamLogger it's possible for the user to leak an Arc> reference which will cause the `Arc::try_unwrap` to fail (if there is more than one single reference). While not ideal, we can recover from this scenario by continuing on and using the Arc> instead of unwrapping it. This will allow us to avoid a possible runtime panic. The downside is there could be two things emitting to the UI at the same time. If that's the case it's the developers responsibility to notice and investigate. Basically: Favor not panic the program when we don't have to due to logging logic. The runtime panics can be caused by: - A poisoned mutex. We could possibly recover but it's new territory https://blog.logrocket.com/understanding-handling-rust-mutex-poisoning/. For now I think if a mutex is poisoned that propagating the panic makes sense. - Closed writer: I don't know when this can happen. Presumably someone could pass in a writer and then close it or the system could error or a file could be deleted etc. In that case we could possibly fallback to generating a new stdout and warn. I'm not sure which is better * Allow wildcard imports to bring in interface It's annoying to have to bring in the structs and then the interface separately. This change allows `commons::output::log::*` and `commons::output::section_log::*` to import the needed traits as well as functions/structs. * Move output::log to output::build_log It's repetitive to have `build_log::BuildLog` but it's otherwise odd that there are logging things that aren't in `mod log`. Now this import `use commons::output::build_log::*;` will give you everything you need to use `BuildLog`. * Test dropping StopJoinGuard stops background logging * Failing test for desired warning formatting Warnings, errors, and information blocks are different from the rest of the other formatting in that they should have some vertical whitespace around them. The logic for this is easy isolation but difficult when combined. ## Newline front & back For example, we could add a newline before and after a block and you would get: ``` ! It's too crowded here ``` But if you issue two warnings back to back you would get: ``` ! It's too crowded here ! It's too crowded here ``` ## Newline front You can partially fix this by only adding a newline to the front only: ``` ! It's too crowded here ! It's too crowded here ``` But if the next thing to print isn't a warning it will be missing a bottom newline ## Newline back ``` ! It's too crowded here ! It's too crowded here ``` That's not right either ## Possible fix I believe that for this to work correctly in all the cases we must store state. ### Save last thing on warn/error/important We could add an option/boolean/whatever to BuildLog to have it store whether or not the last thing that printed was a block and then adjust appropriately. Seems workable but strangely coupled. ### Delayed log We could save blocks and defer them until the next non-block call (or drop) and then emit them all at once. I don't hate that. ### Logging state Introduce an `AnnounceLogger` state or something so when you call `error(self: Box) -> Box`. This state transition could be where we insert the newlines i.e. if you call error on an AnnounceLogger it knows to not add an extra starting newline. The challenge here is getting back to the original state. This is not valid rust code: ``` trait AnnounceLogger { fn error(self: Box, s: &str) -> Box // i.e. how can we get back to SectionLogger, StartedLogger } ``` Now there are only two logger states we would need to return to so we could implement each of them as a separate trait. It's not ideal but it's also not horrible. * Fix warning/important/error formatting using trait As described in the commit that introduced the failing test, this commit implements the "Logging state" trait approach. To emit a warning/error/important to the output we must first `announce()`. As I'm typing this up I realize that there's the case where you can `announce().end_announce()` we could patch this up by introducing an intermediate state that only has error, warn, important on it. I don't like the duplicate code and duplicate trait definition, but the end result seems like a good API. * Refactor data inside of BuildLog Sometimes we pass data that's meant for only a specific log lifecycle (like `TimedStepLogger` while other times it's meant to be propagated throughout the entire build. Moving this data to a purpose defined struct makes this more clear and makes it easier to add additional things later (if we so desire). Ultimately I would like a "warn later" feature. I'm thinking that we can preserve various warnings in a vector. The question is if we want to pass it through the lifecycle of the BuildLog or if we want to put it somewhere as a globally mutable state. # Warn later ## Pass in Build log Would not be able to add a `warn_later` in `section_log` functions as those don't have access to prior BuildLog state. ## Global mutable We can mutate from within `section_log` functions, but well...global mutable state is bad. It might cause headaches ## CNB feature Instead of baking this in at the Rust level we could find a way to expose a folder that all build packs can write to. Originally I was thinking we could have a `setup_delayed_warn` and a `print_delayed_warn` buildpack pair but that only works if all build packs inbetween are successful. This makes me feel like a "run this buildpack even if the ones before it fail" could be a useful feature (or possibly a builder extension spec that would allow heroku to implement this as a vendor specific feature, or possibly a CNB first tier feature). ## Analysis Given this I think the global mutable state is the most promising path forwards. * Add delayed warnings for buildpack authors * Warn later with thread locals The prior implementation of delayed warnings was flawed in that it required manually tracking of global state. Essentially, to work correctly in tests, it needed every test exercising delayed warnings to be guarded via a hidden mutex. This is not good. This new design moves the data to be stored per-thread which ensures no collisions and greatly simplifies logic and possible state. The only down side is that if multiple WarnGuard's are created in a thread, then after the first is dropped, the program cannot tell that another is still in existence so `try_push` will error (which will degrade to a runtime warning in `BuildLog`). If we tracked individual creation/deletion state of a WarnGuard (via a count, for example). Then we could get rid of this error in this edge case. However doing that involves trusting that global (thread) state is updated correctly. In the future we might want to jump through some of those hoops, but for now I'm simply recommending that no more than one WarnGuard per thread be created. This could be enforced by having `new()` return a result if we desired, but I want to keep options open. One other consideration is whether or not a `BuildLog` should automatically create a `WarnGuard` and store it as an `Option`. When created via `buildpack_name`. I like that it takes us from having to initialize two structs to having to initialize one, but dislike that it's effectively hiding functionality, so I didn't do it for now. We could introduce a `enable_delayed_warnings` variant down the line that does this as an opt-in ability. * Allow ReadYourWrite to be cloneable * Refactor ReadYourWrite to return a Reader struct Previously the "reader" returned by this struct was just Arc>, which was fine, but not the most ergonomic. Since I needed a lossy string just about every time I used that struct, I introduced a return that derefs to `Arc>` instead. * Fix warn later extra whitespace fmt::warning is whitespace agnostic. It's up to the BuildLog to enforce vertical whitespace. This matches warn_later output with existing warning output: ``` fn warning(mut self: Box, s: &str) -> Box { writeln_now(&mut self.io, fmt::warning(s.trim())); writeln_now(&mut self.io, ""); self } ``` * Fix CI.yml format * Fix CI section naming * Update rust cache * Failing warn_later test Due to the implementation of the announce logging (warning, important) needing whitespace above and below their blocks, calling `announce.warn_later` accidentally introduce whitespace` into the build output. This test fails: ``` thread 'output::build_log::test::warn_later_doesnt_output_newline' panicked at 'assertion failed: `(left == right)` Diff < left / right > : # 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 ', commons/src/output/build_log.rs:646:9 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace ``` I previously noted that this can also be triggered via calling `.announce().end_announce()` which seemed trivial enough (and unlikely) to avoid. However I'm re-thinking that I want to insert a preliminary guard state between calling `.announce()` and `end_announce()` but it gets gnarly because that intermediate state would carry duplicate associated functions. An alternative could be to move `warn_later` to individual states (instead of needing to create an Announcement logger). * Fix function name * Fix command output in style guide The biggest change here is going from `ps` to `ps aux`. I am also standardizing on the fun run command extension instead of libherokubuildpack's. * Fix failing warn_later_doesnt_output_newline test Previously when entering an "announce" state we would preemptively print a newline. Instead I'm storing a leader character and printing it once and only once while calling one of: - error - important - warning Notably `warn_later` does not emit this character. This also fixes the previously described case where someone enters and exits an announce state without calling error, important, or warning. * Refactor output Announcement interface Previously I had duplication in my interface definitions with SectionAnnounceLogger and StartedAnnounceLogger. I'm using a different technique (associated types) to consolidate those into one trait. At the same time I moved the logic in `build_log.rs` to a shared location (to prevent accidental divergence). I also renamed the struct AnnounceLogger there as it would otherwise conflict with the trait name. The pattern of using an associated type to return to an arbitrary state works well, but I came up with it myself, so it might be gnarly (or there might be a better way to compose this logic). Either way, I think this is better that what we had before. I'm exploring additional ways to clean up the stateful implementation within `build_log.rs` via a thread in our internal slack https://salesforce-internal.slack.com/archives/CFF88C0HM/p1694015747944619 * Better default errors in fun_run commands The default display for fun_run didn't wrap the command. Example: Before: ``` - Debug info - Could not run command gem install bundler --version 2.3.26 --install-dir /layers/heroku_ruby/bundler --bindir /layers/heroku_ruby/bundler/bin --force --no-document --env-shebang. No such file or directory (os error 2) ``` I want to separate fun_run from the build output work, so this approximates the style (without the color coding). It's more readable After: ``` - Debug info - Could not run command `gem install bundler --version 2.3.26 --install-dir /layers/heroku_ruby/bundler --bindir /layers/heroku_ruby/bundler/bin --force --no-document --env-shebang`. No such file or directory (os error 2) ``` * Update metrics buildpack to use new build output * Clean up * Clean up retry logic * Rust 1.73.0 clippy updates * Do not stream `bundle exec rake -P` output or `bundle list` These outputs are meant to be machine readable only, it should be timed and not streamed. I.e. we want the output to be ``` - Rake assets install - Rake detected (`rake` gem found, `Rakefile` found ad `/workspace/Rakefile`) - Running `bundle exec rake -P --trace` .... (2.1s) - Compiling assets with cache (detected `rake assets:precompile` and `rake assets:clean` via `bundle exec rake -P`) ``` And not ``` - Rake assets install - Rake detected (`rake` gem found, `Rakefile` found ad `/workspace/Rakefile`) - Running `bundle exec rake -P --trace` rake about environment rake action_mailbox:ingress:environment rake action_mailbox:ingress:exim action_mailbox:ingress:environment rake action_mailbox:ingress:postfix action_mailbox:ingress:environment rake action_mailbox:ingress:qmail action_mailbox:ingress:environment rake action_mailbox:install rake action_mailbox:install:migrations rake action_text:install rake action_text:install:migrations rake active_storage:install environment rake active_storage:install:migrations rake active_storage:update [...] - Done (2.111s) - Compiling assets with cache (detected `rake assets:precompile` and `rake assets:clean` via `bundle exec rake -P`) ``` * Update build output * Re-run build to demonstrate cached output * Reduce gem install bundler output The output of gem install bundler is an implementation detail and is not needed. Use the more compact timer format instead. * Include error details on framework error * Apply suggestions from code review Co-authored-by: Ed Morley <501702+edmorley@users.noreply.github.com> * Update commons/Cargo.toml Co-authored-by: Ed Morley <501702+edmorley@users.noreply.github.com> * Remove unneeded use newlines and wildcard imports * Fix spelling * Format the barnes gem name * Implement commented out "help" output --------- Co-authored-by: Manuel Fuchs Co-authored-by: Ed Morley <501702+edmorley@users.noreply.github.com> --- .github/workflows/ci.yml | 26 +- Cargo.lock | 227 +++--- buildpacks/ruby/CHANGELOG.md | 4 + buildpacks/ruby/src/gem_list.rs | 40 +- buildpacks/ruby/src/layers.rs | 10 +- .../ruby/src/layers/bundle_download_layer.rs | 128 ++-- .../ruby/src/layers/bundle_install_layer.rs | 132 ++-- .../ruby/src/layers/metrics_agent_install.rs | 31 +- .../ruby/src/layers/ruby_install_layer.rs | 62 +- buildpacks/ruby/src/main.rs | 165 ++-- buildpacks/ruby/src/rake_task_detect.rs | 64 +- .../ruby/src/steps/detect_rake_tasks.rs | 58 +- .../ruby/src/steps/get_default_process.rs | 29 +- .../ruby/src/steps/rake_assets_install.rs | 104 ++- buildpacks/ruby/src/user_errors.rs | 410 +++++++--- buildpacks/ruby/tests/integration_test.rs | 45 +- commons/Cargo.toml | 9 + commons/bin/print_style_guide.rs | 205 +++++ commons/src/build_output.rs | 717 ------------------ commons/src/cache/app_cache_collection.rs | 143 +--- commons/src/fun_run.rs | 340 ++++++++- commons/src/lib.rs | 7 +- commons/src/metadata_digest.rs | 8 +- commons/src/output/background_timer.rs | 157 ++++ commons/src/output/build_log.rs | 707 +++++++++++++++++ commons/src/output/fmt.rs | 337 ++++++++ commons/src/output/interface.rs | 54 ++ commons/src/output/mod.rs | 7 + commons/src/output/section_log.rs | 129 ++++ commons/src/output/util.rs | 186 +++++ commons/src/output/warn_later.rs | 352 +++++++++ 31 files changed, 3373 insertions(+), 1520 deletions(-) create mode 100644 commons/bin/print_style_guide.rs delete mode 100644 commons/src/build_output.rs create mode 100644 commons/src/output/background_timer.rs create mode 100644 commons/src/output/build_log.rs create mode 100644 commons/src/output/fmt.rs create mode 100644 commons/src/output/interface.rs create mode 100644 commons/src/output/mod.rs create mode 100644 commons/src/output/section_log.rs create mode 100644 commons/src/output/util.rs create mode 100644 commons/src/output/warn_later.rs diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b74d655..cb8d9d9 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -59,7 +59,7 @@ jobs: # Runs only tests annotated with the `ignore` attribute (which in this repo, are the integration tests). run: cargo test --locked -- --ignored - pack-getting-started-output: + print-pack-getting-started-output: runs-on: ubuntu-22.04 steps: - name: Checkout @@ -84,6 +84,28 @@ jobs: run: cargo install libcnb-cargo - name: Compile ruby buildpack run: cargo libcnb package - - name: Getting started guide output + - name: "PRINT: Getting started guide output" run: | # Use `script -e -c` to pretend to be a TTY for pack terminal color support script -e -c "pack build my-image --builder heroku/builder:22 --buildpack heroku/nodejs-engine --buildpack packaged/x86_64-unknown-linux-musl/debug/heroku_ruby --path tmp/ruby-getting-started --pull-policy never" + - name: "PRINT: Cached getting started guide output" + run: | # Use `script -e -c` to pretend to be a TTY for pack terminal color support + script -e -c "pack build my-image --builder heroku/builder:22 --buildpack heroku/nodejs-engine --buildpack packaged/x86_64-unknown-linux-musl/debug/heroku_ruby --path tmp/ruby-getting-started --pull-policy never" + + print-style-guide: + runs-on: ubuntu-22.04 + steps: + - name: Checkout + uses: actions/checkout@v3 + - 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.6.2 + - name: Build binary + run: cargo build --bin print_style_guide + - name: "PRINT: Style guide" + run: | # Use `script -e -c` to pretend to be a TTY for pack terminal color support + script -e -c "cargo run --bin print_style_guide" diff --git a/Cargo.lock b/Cargo.lock index 0f24134..a255196 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -65,6 +65,16 @@ dependencies = [ "windows-sys", ] +[[package]] +name = "ascii_table" +version = "4.0.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3c2bee9b9ee0e5768772e38c07ef0ba23a490d7e1336ec7207c25712a2661c55" +dependencies = [ + "lazy_static", + "regex", +] + [[package]] name = "autocfg" version = "1.1.0" @@ -123,12 +133,6 @@ dependencies = [ "serde", ] -[[package]] -name = "bumpalo" -version = "3.14.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7f30e7476521f6f8af1a1c4c0b8cc94f0bee37d91763d0ca2665f299b6cd8aec" - [[package]] name = "byte-unit" version = "4.0.19" @@ -188,9 +192,9 @@ checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" [[package]] name = "clap" -version = "4.4.6" +version = "4.4.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d04704f56c2cde07f43e8e2c154b43f216dc5c92fc98ada720177362f953b956" +checksum = "ac495e00dcec98c83465d5ad66c5c4fabd652fd6686e7c6269b117e729a6f17b" dependencies = [ "clap_builder", "clap_derive", @@ -198,9 +202,9 @@ dependencies = [ [[package]] name = "clap_builder" -version = "4.4.6" +version = "4.4.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0e231faeaca65ebd1ea3c737966bf858971cd38c3849107aa3ea7de90a804e45" +checksum = "c77ed9a32a62e6ca27175d00d29d05ca32e396ea1eb5fb01d8256b669cec7663" dependencies = [ "anstream", "anstyle", @@ -210,9 +214,9 @@ dependencies = [ [[package]] name = "clap_derive" -version = "4.4.2" +version = "4.4.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0862016ff20d69b84ef8247369fabf5c008a7417002411897d40ee1f4532b873" +checksum = "cf9804afaaf59a91e75b022a30fb7229a7901f60c755489cc61c9b423b836442" dependencies = [ "heck", "proc-macro2", @@ -222,9 +226,9 @@ dependencies = [ [[package]] name = "clap_lex" -version = "0.5.1" +version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cd7cc57abe963c6d3b9d8be5b06ba7c8957a930305ca90304f24ef040aa6f961" +checksum = "702fc72eb24e5a1e48ce58027a675bc24edd52096d5397d4aea7c6dd9eca0bd1" [[package]] name = "colorchoice" @@ -236,7 +240,9 @@ checksum = "acbf1af155f9b9ef647e42cdc158db4b64a1b61f743629225fde6f3e0be2a7c7" name = "commons" version = "0.1.0" dependencies = [ + "ascii_table", "byte-unit", + "const_format", "fancy-regex", "filetime", "fs-err", @@ -245,7 +251,9 @@ dependencies = [ "indoc", "lazy_static", "libcnb", + "libcnb-test", "libherokubuildpack", + "pretty_assertions", "regex", "serde", "sha2", @@ -256,11 +264,31 @@ dependencies = [ "which_problem", ] +[[package]] +name = "const_format" +version = "0.2.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c990efc7a285731f9a4378d81aff2f0e85a2c8781a05ef0f8baa8dac54d0ff48" +dependencies = [ + "const_format_proc_macros", +] + +[[package]] +name = "const_format_proc_macros" +version = "0.2.31" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e026b6ce194a874cb9cf32cd5772d1ef9767cc8fcb5765948d74f37a9d8b2bf6" +dependencies = [ + "proc-macro2", + "quote", + "unicode-xid", +] + [[package]] name = "cpufeatures" -version = "0.2.10" +version = "0.2.11" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3fbc60abd742b35f2492f808e1abbb83d45f72db402e14c55057edc9c7b1e9e4" +checksum = "ce420fe07aecd3e67c5f910618fe65e94158f6dcc0adf44e00d69ce2bdfe0fd0" dependencies = [ "libc", ] @@ -317,6 +345,12 @@ dependencies = [ "typenum", ] +[[package]] +name = "diff" +version = "0.1.13" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "56254986775e3233ffa9c4d7d3faaf6d36a2c09d30b20687e9f88bc8bafc16c8" + [[package]] name = "digest" version = "0.10.7" @@ -373,7 +407,7 @@ checksum = "d4029edd3e734da6fe05b6cd7bd2960760a616bd2ddd0d59a0124746d6272af0" dependencies = [ "cfg-if", "libc", - "redox_syscall", + "redox_syscall 0.3.5", "windows-sys", ] @@ -573,15 +607,6 @@ version = "1.0.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "af150ab688ff2122fcef229be89cb50dd66af9e01a4ff320cc137eecc9bacc38" -[[package]] -name = "js-sys" -version = "0.3.64" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c5f195fe497f702db0f318b07fdd68edb16955aed830df8363d837542f8f935a" -dependencies = [ - "wasm-bindgen", -] - [[package]] name = "lazy_static" version = "1.4.0" @@ -798,6 +823,16 @@ version = "0.2.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5b40af805b3121feab8a3c29f04d8ad262fa8e0561883e7653e024ae4479e6de" +[[package]] +name = "pretty_assertions" +version = "1.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "af7cee1a6c8a5b9208b3cb1061f10c0cb689087b3d8ce85fb9d2dd7a29b6ba66" +dependencies = [ + "diff", + "yansi", +] + [[package]] name = "proc-macro2" version = "1.0.69" @@ -875,6 +910,15 @@ dependencies = [ "bitflags 1.3.2", ] +[[package]] +name = "redox_syscall" +version = "0.4.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4722d768eff46b75989dd134e5c353f0d6296e5aaa3132e776cbdb56be7731aa" +dependencies = [ + "bitflags 1.3.2", +] + [[package]] name = "regex" version = "1.10.2" @@ -906,24 +950,23 @@ checksum = "c08c74e62047bb2de4ff487b251e4a92e24f48745648451635cec7d591162d9f" [[package]] name = "ring" -version = "0.16.20" +version = "0.17.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3053cf52e236a3ed746dfc745aa9cacf1b791d846bdaf412f60a8d7d6e17c8fc" +checksum = "fb0205304757e5d899b9c2e448b867ffd03ae7f988002e47cd24954391394d0b" dependencies = [ "cc", + "getrandom", "libc", - "once_cell", "spin", "untrusted", - "web-sys", - "winapi", + "windows-sys", ] [[package]] name = "rustix" -version = "0.38.20" +version = "0.38.21" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "67ce50cb2e16c2903e30d1cbccfd8387a74b9d4c938b6a4c5ec6cc7556f7a8a0" +checksum = "2b426b0506e5d50a7d8dafcf2e81471400deb602392c7dd110815afb4eaf02a3" dependencies = [ "bitflags 2.4.1", "errno", @@ -934,9 +977,9 @@ dependencies = [ [[package]] name = "rustls" -version = "0.21.7" +version = "0.21.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cd8d6c9f025a446bc4d18ad9632e69aec8f287aa84499ee335599fabd20c3fd8" +checksum = "446e14c5cda4f3f30fe71863c34ec70f5ac79d6087097ad0bb433e1be5edf04c" dependencies = [ "log", "ring", @@ -946,9 +989,9 @@ dependencies = [ [[package]] name = "rustls-webpki" -version = "0.101.6" +version = "0.101.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "3c7d5dece342910d9ba34d259310cae3e0154b873b35408b787b59bce53d34fe" +checksum = "8b6275d1ee7a1cd780b64aca7726599a1dbc893b1e64144529e55c3c2f745765" dependencies = [ "ring", "untrusted", @@ -977,9 +1020,9 @@ checksum = "94143f37725109f92c262ed2cf5e59bce7498c01bcc1502d7b9afe439a4e9f49" [[package]] name = "sct" -version = "0.7.0" +version = "0.7.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d53dcdb7c9f8158937a7981b48accfd39a43af418591a5d008c7b22b5e1b7ca4" +checksum = "da046153aa2352493d6cb7da4b6e5c0c057d8a1d0a9aa8560baffdd945acd414" dependencies = [ "ring", "untrusted", @@ -996,18 +1039,18 @@ dependencies = [ [[package]] name = "serde" -version = "1.0.189" +version = "1.0.190" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8e422a44e74ad4001bdc8eede9a4570ab52f71190e9c076d14369f38b9200537" +checksum = "91d3c334ca1ee894a2c6f6ad698fe8c435b76d504b13d436f0685d648d6d96f7" dependencies = [ "serde_derive", ] [[package]] name = "serde_derive" -version = "1.0.189" +version = "1.0.190" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1e48d1f918009ce3145511378cf68d613e3b3d9137d67272562080d68a2b32d5" +checksum = "67c5609f394e5c2bd7fc51efda478004ea80ef42fee983d5c67a65e34f32c0e3" dependencies = [ "proc-macro2", "quote", @@ -1047,9 +1090,9 @@ dependencies = [ [[package]] name = "spin" -version = "0.5.2" +version = "0.9.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6e63cff320ae2c57904679ba7cb63280a3dc4613885beafb148ee7bf9aa9042d" +checksum = "6980e8d7511241f8acf4aebddbb1ff938df5eebe98691418c4468d0b72a96a67" [[package]] name = "strsim" @@ -1081,13 +1124,13 @@ dependencies = [ [[package]] name = "tempfile" -version = "3.8.0" +version = "3.8.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "cb94d2f3cc536af71caac6b6fcebf65860b347e7ce0cc9ebe8f70d3e521054ef" +checksum = "7ef1adac450ad7f4b3c28589471ade84f25f731a7a0fe30d71dfa9f60fd808e5" dependencies = [ "cfg-if", "fastrand", - "redox_syscall", + "redox_syscall 0.4.1", "rustix", "windows-sys", ] @@ -1148,9 +1191,9 @@ checksum = "1f3ccbac311fea05f86f61904b462b55fb3df8837a366dfc601a0161d0532f20" [[package]] name = "toml" -version = "0.8.4" +version = "0.8.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2ef75d881185fd2df4a040793927c153d863651108a93c7e17a9e591baa95cc6" +checksum = "8ff9e3abce27ee2c9a37f9ad37238c1bdd4e789c84ba37df76aa4d528f5072cc" dependencies = [ "serde", "serde_spanned", @@ -1169,9 +1212,9 @@ dependencies = [ [[package]] name = "toml_edit" -version = "0.20.4" +version = "0.20.7" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "380f9e8120405471f7c9ad1860a713ef5ece6a670c7eae39225e477340f32fc4" +checksum = "70f427fce4d84c72b5b732388bf4a9f4531b53f74e2887e3ecb2481f68f66d81" dependencies = [ "indexmap", "serde", @@ -1207,11 +1250,17 @@ dependencies = [ "tinyvec", ] +[[package]] +name = "unicode-xid" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f962df74c8c05a667b5ee8bcf162993134c104e96440b663c8daa176dc772d8c" + [[package]] name = "untrusted" -version = "0.7.1" +version = "0.9.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a156c684c91ea7d62626509bce3cb4e1d9ed5c4d978f7b4352658f96a4c26b4a" +checksum = "8ecb6da28b8a351d773b68d5825ac39017e680750f980f3a1a85cd8dd28a47c1" [[package]] name = "ureq" @@ -1290,70 +1339,6 @@ version = "0.11.0+wasi-snapshot-preview1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423" -[[package]] -name = "wasm-bindgen" -version = "0.2.87" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7706a72ab36d8cb1f80ffbf0e071533974a60d0a308d01a5d0375bf60499a342" -dependencies = [ - "cfg-if", - "wasm-bindgen-macro", -] - -[[package]] -name = "wasm-bindgen-backend" -version = "0.2.87" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5ef2b6d3c510e9625e5fe6f509ab07d66a760f0885d858736483c32ed7809abd" -dependencies = [ - "bumpalo", - "log", - "once_cell", - "proc-macro2", - "quote", - "syn", - "wasm-bindgen-shared", -] - -[[package]] -name = "wasm-bindgen-macro" -version = "0.2.87" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "dee495e55982a3bd48105a7b947fd2a9b4a8ae3010041b9e0faab3f9cd028f1d" -dependencies = [ - "quote", - "wasm-bindgen-macro-support", -] - -[[package]] -name = "wasm-bindgen-macro-support" -version = "0.2.87" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "54681b18a46765f095758388f2d0cf16eb8d4169b639ab575a8f5693af210c7b" -dependencies = [ - "proc-macro2", - "quote", - "syn", - "wasm-bindgen-backend", - "wasm-bindgen-shared", -] - -[[package]] -name = "wasm-bindgen-shared" -version = "0.2.87" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ca6ad05a4870b2bf5fe995117d3728437bd27d7cd5f06f13c17443ef369775a1" - -[[package]] -name = "web-sys" -version = "0.3.64" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "9b85cbef8c220a6abc02aefd892dfc0fc23afb1c6a426316ec33253a3877249b" -dependencies = [ - "js-sys", - "wasm-bindgen", -] - [[package]] name = "webpki-roots" version = "0.25.2" @@ -1499,3 +1484,9 @@ checksum = "f4686009f71ff3e5c4dbcf1a282d0a44db3f021ba69350cd42086b3e5f1c6985" dependencies = [ "libc", ] + +[[package]] +name = "yansi" +version = "0.5.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09041cd90cf85f7f8b2df60c646f853b7f535ce68f85244eb6731cf89fa498ec" diff --git a/buildpacks/ruby/CHANGELOG.md b/buildpacks/ruby/CHANGELOG.md index 23f21c0..21f9859 100644 --- a/buildpacks/ruby/CHANGELOG.md +++ b/buildpacks/ruby/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- Update build logging style (https://github.com/heroku/buildpacks-ruby/pull/198) + ## [2.1.1] - 2023-10-24 ### Fixed diff --git a/buildpacks/ruby/src/gem_list.rs b/buildpacks/ruby/src/gem_list.rs index ee65a42..50a41be 100644 --- a/buildpacks/ruby/src/gem_list.rs +++ b/buildpacks/ruby/src/gem_list.rs @@ -1,6 +1,9 @@ -use crate::build_output::{RunCommand, Section}; -use commons::fun_run::{self, CmdMapExt}; +use commons::fun_run::{CmdError, CommandWithName}; use commons::gem_version::GemVersion; +use commons::output::{ + fmt, + section_log::{log_step_timed, SectionLogger}, +}; use core::str::FromStr; use regex::Regex; use std::collections::HashMap; @@ -15,12 +18,6 @@ pub struct GemList { pub gems: HashMap, } -#[derive(thiserror::Error, Debug)] -pub enum ListError { - #[error("Error determining dependencies: \n{0}")] - BundleListShellCommandError(fun_run::CmdError), -} - /// Converts the output of `$ gem list` into a data structure that can be inspected and compared /// /// ``` @@ -62,19 +59,20 @@ impl GemList { /// # Errors /// /// Errors if the command `bundle list` is unsuccessful. - pub fn from_bundle_list, K: AsRef, V: AsRef>( - envs: T, - build_output: &Section, - ) -> Result { - let output = Command::new("bundle") - .arg("list") - .env_clear() - .envs(envs) - .cmd_map(|cmd| build_output.run(RunCommand::inline_progress(cmd))) - .map_err(ListError::BundleListShellCommandError)?; + pub fn from_bundle_list(envs: T, _logger: &dyn SectionLogger) -> Result + where + T: IntoIterator, + K: AsRef, + V: AsRef, + { + let mut cmd = Command::new("bundle"); + cmd.arg("list").env_clear().envs(envs); + + let output = log_step_timed(format!("Running {}", fmt::command(cmd.name())), || { + cmd.named_output() + })?; - let stdout = String::from_utf8_lossy(&output.stdout); - GemList::from_str(&stdout) + GemList::from_str(&output.stdout_lossy()) } #[must_use] @@ -84,7 +82,7 @@ impl GemList { } impl FromStr for GemList { - type Err = ListError; + type Err = CmdError; fn from_str(string: &str) -> Result { // https://regex101.com/r/EIJe5G/1 diff --git a/buildpacks/ruby/src/layers.rs b/buildpacks/ruby/src/layers.rs index 62c0063..4c00f50 100644 --- a/buildpacks/ruby/src/layers.rs +++ b/buildpacks/ruby/src/layers.rs @@ -1,8 +1,4 @@ -mod bundle_download_layer; -mod bundle_install_layer; +pub(crate) mod bundle_download_layer; +pub(crate) mod bundle_install_layer; pub(crate) mod metrics_agent_install; -mod ruby_install_layer; - -pub(crate) use self::bundle_download_layer::BundleDownloadLayer; -pub(crate) use self::bundle_install_layer::BundleInstallLayer; -pub(crate) use self::ruby_install_layer::{RubyInstallError, RubyInstallLayer}; +pub(crate) mod ruby_install_layer; diff --git a/buildpacks/ruby/src/layers/bundle_download_layer.rs b/buildpacks/ruby/src/layers/bundle_download_layer.rs index 14d45ba..12867a8 100644 --- a/buildpacks/ruby/src/layers/bundle_download_layer.rs +++ b/buildpacks/ruby/src/layers/bundle_download_layer.rs @@ -1,7 +1,11 @@ -use crate::build_output::{RunCommand, Section}; +use commons::output::{ + fmt, + section_log::{log_step, log_step_timed, SectionLogger}, +}; + use crate::RubyBuildpack; use crate::RubyBuildpackError; -use commons::fun_run::{self, CmdMapExt}; +use commons::fun_run::{self, CommandWithName}; use commons::gemfile_lock::ResolvedBundlerVersion; use libcnb::build::BuildContext; use libcnb::data::layer_content_metadata::LayerTypes; @@ -14,7 +18,7 @@ use std::process::Command; #[derive(Deserialize, Serialize, Debug, Clone)] pub(crate) struct BundleDownloadLayerMetadata { - version: ResolvedBundlerVersion, + pub version: ResolvedBundlerVersion, } /// # Install the bundler gem @@ -23,13 +27,13 @@ pub(crate) struct BundleDownloadLayerMetadata { /// /// Installs a copy of `bundler` to the `` with a bundler executable in /// `/bin`. Must run before [`crate.steps.bundle_install`]. -pub(crate) struct BundleDownloadLayer { +pub(crate) struct BundleDownloadLayer<'a> { pub env: Env, - pub version: ResolvedBundlerVersion, - pub build_output: Section, + pub metadata: BundleDownloadLayerMetadata, + pub _section_logger: &'a dyn SectionLogger, } -impl Layer for BundleDownloadLayer { +impl<'a> Layer for BundleDownloadLayer<'a> { type Buildpack = RubyBuildpack; type Metadata = BundleDownloadLayerMetadata; @@ -40,6 +44,7 @@ impl Layer for BundleDownloadLayer { cache: true, } } + fn create( &self, _context: &BuildContext, @@ -48,57 +53,56 @@ impl Layer for BundleDownloadLayer { let bin_dir = layer_path.join("bin"); let gem_path = layer_path; - Command::new("gem") - .args([ - "install", - "bundler", - "--version", // Specify exact version to install - &self.version.to_string(), - ]) - .env_clear() - .envs(&self.env) - .cmd_map(|cmd| { - // Format `gem install --version ` without other content for display - let name = fun_run::display(cmd); - // Arguments we don't need in the output - cmd.args([ - "--install-dir", // Directory where bundler's contents will live - &layer_path.to_string_lossy(), - "--bindir", // Directory where `bundle` executable lives - &bin_dir.to_string_lossy(), - "--force", - "--no-document", // Don't install ri or rdoc documentation, which takes extra time - "--env-shebang", // Start the `bundle` executable with `#! /usr/bin/env ruby` - ]); - self.build_output - .run(RunCommand::inline_progress(cmd).with_name(name)) - .map_err(|error| { - fun_run::map_which_problem(error, cmd, self.env.get("PATH").cloned()) - }) - }) - .map_err(RubyBuildpackError::GemInstallBundlerCommandError)?; + let mut cmd = Command::new("gem"); + cmd.args([ + "install", + "bundler", + "--version", // Specify exact version to install + &self.metadata.version.to_string(), + ]) + .env_clear() + .envs(&self.env); - LayerResultBuilder::new(BundleDownloadLayerMetadata { - version: self.version.clone(), + // Format `gem install --version ` without other content for display + let short_name = fun_run::display(&mut cmd); + + // Arguments we don't need in the output + cmd.args([ + "--install-dir", // Directory where bundler's contents will live + &layer_path.to_string_lossy(), + "--bindir", // Directory where `bundle` executable lives + &bin_dir.to_string_lossy(), + "--force", // Overwrite if it already exists + "--no-document", // Don't install ri or rdoc documentation, which takes extra time + "--env-shebang", // Start the `bundle` executable with `#! /usr/bin/env ruby` + ]); + + log_step_timed(format!("Running {}", fmt::command(short_name)), || { + cmd.named_output().map_err(|error| { + fun_run::map_which_problem(error, cmd.mut_cmd(), self.env.get("PATH").cloned()) + }) }) - .env( - LayerEnv::new() - .chainable_insert(Scope::All, ModificationBehavior::Delimiter, "PATH", ":") - .chainable_insert( - Scope::All, - ModificationBehavior::Prepend, - "PATH", // Ensure this path comes before default bundler that ships with ruby, don't rely on the lifecycle - bin_dir, - ) - .chainable_insert(Scope::All, ModificationBehavior::Delimiter, "GEM_PATH", ":") - .chainable_insert( - Scope::All, - ModificationBehavior::Prepend, - "GEM_PATH", // Bundler is a gem too, allow it to be required - gem_path, - ), - ) - .build() + .map_err(RubyBuildpackError::GemInstallBundlerCommandError)?; + + LayerResultBuilder::new(self.metadata.clone()) + .env( + LayerEnv::new() + .chainable_insert(Scope::All, ModificationBehavior::Delimiter, "PATH", ":") + .chainable_insert( + Scope::All, + ModificationBehavior::Prepend, + "PATH", // Ensure this path comes before default bundler that ships with ruby, don't rely on the lifecycle + bin_dir, + ) + .chainable_insert(Scope::All, ModificationBehavior::Delimiter, "GEM_PATH", ":") + .chainable_insert( + Scope::All, + ModificationBehavior::Prepend, + "GEM_PATH", // Bundler is a gem too, allow it to be required + gem_path, + ), + ) + .build() } fn existing_layer_strategy( @@ -107,18 +111,18 @@ impl Layer for BundleDownloadLayer { layer_data: &LayerData, ) -> Result { let old = &layer_data.content_metadata.metadata; - let now = BundleDownloadLayerMetadata { - version: self.version.clone(), - }; + let now = self.metadata.clone(); match cache_state(old.clone(), now) { State::NothingChanged(_version) => { - self.build_output.say("Using cached version"); + log_step("Using cached version"); Ok(ExistingLayerStrategy::Keep) } State::BundlerVersionChanged(_old, _now) => { - self.build_output - .say_with_details("Clearing cache", "bundler version changed"); + log_step(format!( + "Clearing cache {}", + fmt::details("bundler version changed") + )); Ok(ExistingLayerStrategy::Recreate) } diff --git a/buildpacks/ruby/src/layers/bundle_install_layer.rs b/buildpacks/ruby/src/layers/bundle_install_layer.rs index 481bc71..cad034f 100644 --- a/buildpacks/ruby/src/layers/bundle_install_layer.rs +++ b/buildpacks/ruby/src/layers/bundle_install_layer.rs @@ -1,10 +1,13 @@ -use crate::{ - build_output::{self, RunCommand, Section}, - BundleWithout, RubyBuildpack, RubyBuildpackError, +use commons::output::{ + fmt::{self, HELP}, + section_log::{log_step, log_step_stream, SectionLogger}, }; + +use crate::{BundleWithout, RubyBuildpack, RubyBuildpackError}; +use commons::fun_run::CommandWithName; use commons::{ display::SentenceList, - fun_run::{self, CmdError, CmdMapExt}, + fun_run::{self, CmdError}, gemfile_lock::ResolvedRubyVersion, metadata_digest::MetadataDigest, }; @@ -19,7 +22,7 @@ use serde::{Deserialize, Serialize}; use std::{path::Path, process::Command}; const HEROKU_SKIP_BUNDLE_DIGEST: &str = "HEROKU_SKIP_BUNDLE_DIGEST"; -const FORCE_BUNDLE_INSTALL_CACHE_KEY: &str = "v1"; +pub(crate) const FORCE_BUNDLE_INSTALL_CACHE_KEY: &str = "v1"; /// Mostly runs 'bundle install' /// @@ -29,18 +32,18 @@ const FORCE_BUNDLE_INSTALL_CACHE_KEY: &str = "v1"; /// To help achieve this the logic inside of `BundleInstallLayer::update` and /// `BundleInstallLayer::create` are the same. #[derive(Debug)] -pub(crate) struct BundleInstallLayer { +pub(crate) struct BundleInstallLayer<'a> { pub env: Env, pub without: BundleWithout, - pub ruby_version: ResolvedRubyVersion, - pub build_output: Section, + pub _section_log: &'a dyn SectionLogger, + pub metadata: BundleInstallLayerMetadata, } #[derive(Deserialize, Serialize, Debug, Clone, Eq, PartialEq)] pub(crate) struct BundleInstallLayerMetadata { - stack: StackId, - ruby_version: ResolvedRubyVersion, - force_bundle_install_key: String, + pub stack: StackId, + pub ruby_version: ResolvedRubyVersion, + pub force_bundle_install_key: String, /// A struct that holds the cryptographic hash of components that can /// affect the result of `bundle install`. When these values do not @@ -53,36 +56,10 @@ pub(crate) struct BundleInstallLayerMetadata { /// This value is cached with metadata, so changing the struct /// may cause metadata to be invalidated (and the cache cleared). /// - digest: MetadataDigest, // Must be last for serde to be happy https://github.com/toml-rs/toml-rs/issues/142 + pub digest: MetadataDigest, // Must be last for serde to be happy https://github.com/toml-rs/toml-rs/issues/142 } -impl BundleInstallLayer { - fn build_metadata( - &self, - context: &BuildContext, - _layer_path: &Path, - ) -> Result { - let digest = MetadataDigest::new_env_files( - &context.platform, - &[ - &context.app_dir.join("Gemfile"), - &context.app_dir.join("Gemfile.lock"), - ], - ) - .map_err(RubyBuildpackError::BundleInstallDigestError)?; - - let stack = context.stack_id.clone(); - let ruby_version = self.ruby_version.clone(); - let force_bundle_install_key = String::from(FORCE_BUNDLE_INSTALL_CACHE_KEY); - - Ok(BundleInstallLayerMetadata { - stack, - ruby_version, - force_bundle_install_key, - digest, - }) - } - +impl<'a> BundleInstallLayer<'a> { #[allow(clippy::unnecessary_wraps)] fn build_layer_env( &self, @@ -128,7 +105,7 @@ fn update_state(old: &BundleInstallLayerMetadata, now: &BundleInstallLayerMetada } } -impl Layer for BundleInstallLayer { +impl Layer for BundleInstallLayer<'_> { type Buildpack = RubyBuildpack; type Metadata = BundleInstallLayerMetadata; @@ -145,28 +122,28 @@ impl Layer for BundleInstallLayer { context: &BuildContext, layer_data: &LayerData, ) -> Result, RubyBuildpackError> { - let metadata = self.build_metadata(context, &layer_data.path)?; + let metadata = self.metadata.clone(); let layer_env = self.build_layer_env(context, &layer_data.path)?; let env = layer_env.apply(Scope::Build, &self.env); match update_state(&layer_data.content_metadata.metadata, &metadata) { UpdateState::Run(reason) => { - self.build_output.say(reason); + log_step(reason); - bundle_install(&env, &self.build_output) - .map_err(RubyBuildpackError::BundleInstallCommandError)?; + bundle_install(&env).map_err(RubyBuildpackError::BundleInstallCommandError)?; } UpdateState::Skip(checked) => { - let checked = SentenceList::new(&checked).join_str("or"); - let bundle_install = build_output::fmt::value("bundle install"); - let env_var = build_output::fmt::value(format!("{HEROKU_SKIP_BUNDLE_DIGEST}=1")); - - self.build_output.say_with_details( - format!("Skipping {bundle_install}"), - format!("no changes found in {checked}"), - ); - self.build_output - .help(format!("To force run {bundle_install} set {env_var}")); + let bundle_install = fmt::value("bundle install"); + + log_step(format!( + "Skipping {bundle_install} (no changes found in {sources})", + sources = SentenceList::new(&checked).join_str("or") + )); + + log_step(format!( + "{HELP} To force run {bundle_install} set {}", + fmt::value(format!("{HEROKU_SKIP_BUNDLE_DIGEST}=1")) + )); } } @@ -179,14 +156,14 @@ impl Layer for BundleInstallLayer { context: &BuildContext, layer_path: &Path, ) -> Result, RubyBuildpackError> { - let metadata = self.build_metadata(context, layer_path)?; let layer_env = self.build_layer_env(context, layer_path)?; let env = layer_env.apply(Scope::Build, &self.env); - bundle_install(&env, &self.build_output) - .map_err(RubyBuildpackError::BundleInstallCommandError)?; + bundle_install(&env).map_err(RubyBuildpackError::BundleInstallCommandError)?; - LayerResultBuilder::new(metadata).env(layer_env).build() + LayerResultBuilder::new(self.metadata.clone()) + .env(layer_env) + .build() } /// When there is a cache determines if we will run: @@ -198,30 +175,31 @@ impl Layer for BundleInstallLayer { /// create is run. fn existing_layer_strategy( &self, - context: &BuildContext, + _context: &BuildContext, layer_data: &LayerData, ) -> Result { let old = &layer_data.content_metadata.metadata; - let now = self.build_metadata(context, &layer_data.path)?; + let now = self.metadata.clone(); let clear_and_run = Ok(ExistingLayerStrategy::Recreate); let keep_and_run = Ok(ExistingLayerStrategy::Update); match cache_state(old.clone(), now) { Changed::Nothing => { - self.build_output.say("Loading cache"); + log_step("Loading cache"); keep_and_run } Changed::Stack(_old, _now) => { - self.build_output - .say_with_details("Clearing cache", "stack changed"); + log_step(format!("Clearing cache {}", fmt::details("stack changed"))); clear_and_run } Changed::RubyVersion(_old, _now) => { - self.build_output - .say_with_details("Clearing cache", "ruby version changed"); + log_step(format!( + "Clearing cache {}", + fmt::details("ruby version changed") + )); clear_and_run } @@ -328,7 +306,8 @@ fn layer_env(layer_path: &Path, app_dir: &Path, without_default: &BundleWithout) /// /// When the 'bundle install' command fails this function returns an error. /// -fn bundle_install(env: &Env, section: &Section) -> Result<(), CmdError> { +fn bundle_install(env: &Env) -> Result<(), CmdError> { + let path_env = env.get("PATH").cloned(); let display_with_env = |cmd: &'_ mut Command| { fun_run::display_with_env_keys( cmd, @@ -345,18 +324,17 @@ fn bundle_install(env: &Env, section: &Section) -> Result<(), CmdError> { }; // ## Run `$ bundle install` - Command::new("bundle") - .env_clear() // Current process env vars already merged into env + let mut cmd = Command::new("bundle"); + cmd.env_clear() // Current process env vars already merged into env .args(["install"]) - .envs(env) - .cmd_map(|cmd| { - let name = display_with_env(cmd); - let path_env = env.get("PATH").cloned(); - - section - .run(RunCommand::stream(cmd).with_name(name)) - .map_err(|error| fun_run::map_which_problem(error, cmd, path_env)) - })?; + .envs(env); + + let mut cmd = cmd.named_fn(display_with_env); + + log_step_stream(format!("Running {}", fmt::command(cmd.name())), |stream| { + cmd.stream_output(stream.io(), stream.io()) + }) + .map_err(|error| fun_run::map_which_problem(error, cmd.mut_cmd(), path_env))?; Ok(()) } diff --git a/buildpacks/ruby/src/layers/metrics_agent_install.rs b/buildpacks/ruby/src/layers/metrics_agent_install.rs index 0e3dc1a..d1400c3 100644 --- a/buildpacks/ruby/src/layers/metrics_agent_install.rs +++ b/buildpacks/ruby/src/layers/metrics_agent_install.rs @@ -1,5 +1,5 @@ -use crate::build_output; use crate::{RubyBuildpack, RubyBuildpackError}; +use commons::output::section_log::{log_step, log_step_timed, SectionLogger}; use flate2::read::GzDecoder; use libcnb::data::layer_content_metadata::LayerTypes; use libcnb::layer::ExistingLayerStrategy; @@ -30,8 +30,8 @@ const DOWNLOAD_URL: &str = const DOWNLOAD_SHA: &str = "f9bf9f33c949e15ffed77046ca38f8dae9307b6a0181c6af29a25dec46eb2dac"; #[derive(Debug)] -pub(crate) struct MetricsAgentInstall { - pub(crate) section: build_output::Section, +pub(crate) struct MetricsAgentInstall<'a> { + pub _in_section: &'a dyn SectionLogger, // force the layer to be called within a Section logging context, not necessary but it's safer } #[derive(Deserialize, Serialize, Debug, Clone)] @@ -64,7 +64,7 @@ pub(crate) enum MetricsAgentInstallError { ChecksumFailed(String), } -impl Layer for MetricsAgentInstall { +impl<'a> Layer for MetricsAgentInstall<'a> { type Buildpack = RubyBuildpack; type Metadata = Metadata; @@ -86,12 +86,11 @@ impl Layer for MetricsAgentInstall { > { let bin_dir = layer_path.join("bin"); - let mut timer = self.section.say_with_inline_timer("Downloading"); - let agentmon = install_agentmon(&bin_dir).map_err(RubyBuildpackError::MetricsAgentError)?; - - timer.done(); + let agentmon = log_step_timed("Downloading", || { + install_agentmon(&bin_dir).map_err(RubyBuildpackError::MetricsAgentError) + })?; - self.section.say("Writing scripts"); + log_step("Writing scripts"); let execd = write_execd_script(&agentmon, layer_path) .map_err(RubyBuildpackError::MetricsAgentError)?; @@ -112,14 +111,14 @@ impl Layer for MetricsAgentInstall { > { let layer_path = &layer_data.path; - self.section.say("Writing scripts"); + log_step("Writing scripts"); let execd = write_execd_script(&layer_path.join("bin").join("agentmon"), layer_path) .map_err(RubyBuildpackError::MetricsAgentError)?; LayerResultBuilder::new(Metadata { download_url: Some(DOWNLOAD_URL.to_string()), }) - .exec_d_program("spawn agentmon", execd) + .exec_d_program("spawn_metrics_agent", execd) .build() } @@ -131,12 +130,13 @@ impl Layer for MetricsAgentInstall { { match &layer_data.content_metadata.metadata.download_url { Some(url) if url == DOWNLOAD_URL => { - self.section.say("Using cached metrics agent"); + log_step("Using cached metrics agent"); Ok(ExistingLayerStrategy::Update) } Some(url) => { - self.section - .say_with_details("Updating metrics agent", format!("{url} to {DOWNLOAD_URL}")); + log_step(format!( + "Using cached metrics agent ({url} to {DOWNLOAD_URL}" + )); Ok(ExistingLayerStrategy::Recreate) } None => Ok(ExistingLayerStrategy::Recreate), @@ -151,8 +151,7 @@ impl Layer for MetricsAgentInstall { libcnb::layer::MetadataMigration, ::Error, > { - self.section - .say_with_details("Clearing cache", "invalid metadata"); + log_step("Clearing cache (invalid metadata)"); Ok(libcnb::layer::MetadataMigration::RecreateLayer) } diff --git a/buildpacks/ruby/src/layers/ruby_install_layer.rs b/buildpacks/ruby/src/layers/ruby_install_layer.rs index 5d45447..d34ac6d 100644 --- a/buildpacks/ruby/src/layers/ruby_install_layer.rs +++ b/buildpacks/ruby/src/layers/ruby_install_layer.rs @@ -1,4 +1,9 @@ -use crate::{build_output, RubyBuildpack, RubyBuildpackError}; +use commons::output::{ + fmt::{self}, + section_log::{log_step, log_step_timed, SectionLogger}, +}; + +use crate::{RubyBuildpack, RubyBuildpackError}; use commons::gemfile_lock::ResolvedRubyVersion; use flate2::read::GzDecoder; use libcnb::build::BuildContext; @@ -25,10 +30,9 @@ use url::Url; /// /// When the Ruby version changes, invalidate and re-run. /// -#[derive(PartialEq, Eq)] -pub(crate) struct RubyInstallLayer { - pub version: ResolvedRubyVersion, - pub build_output: build_output::Section, +pub(crate) struct RubyInstallLayer<'a> { + pub _in_section: &'a dyn SectionLogger, // force the layer to be called within a Section logging context, not necessary but it's safer + pub metadata: RubyInstallLayerMetadata, } #[derive(Deserialize, Serialize, Debug, Clone)] @@ -37,7 +41,7 @@ pub(crate) struct RubyInstallLayerMetadata { pub version: ResolvedRubyVersion, } -impl Layer for RubyInstallLayer { +impl<'a> Layer for RubyInstallLayer<'a> { type Buildpack = RubyBuildpack; type Metadata = RubyInstallLayerMetadata; @@ -51,58 +55,50 @@ impl Layer for RubyInstallLayer { fn create( &self, - context: &BuildContext, + _context: &BuildContext, layer_path: &Path, ) -> Result, RubyBuildpackError> { - let mut timer = self.build_output.say_with_inline_timer("Installing"); - - let tmp_ruby_tgz = NamedTempFile::new() - .map_err(RubyInstallError::CouldNotCreateDestinationFile) - .map_err(RubyBuildpackError::RubyInstallError)?; + log_step_timed("Installing", || { + let tmp_ruby_tgz = NamedTempFile::new() + .map_err(RubyInstallError::CouldNotCreateDestinationFile) + .map_err(RubyBuildpackError::RubyInstallError)?; - let url = download_url(&context.stack_id, &self.version) - .map_err(RubyBuildpackError::RubyInstallError)?; + let url = download_url(&self.metadata.stack, &self.metadata.version) + .map_err(RubyBuildpackError::RubyInstallError)?; - download(url.as_ref(), tmp_ruby_tgz.path()) - .map_err(RubyBuildpackError::RubyInstallError)?; + download(url.as_ref(), tmp_ruby_tgz.path()) + .map_err(RubyBuildpackError::RubyInstallError)?; - untar(tmp_ruby_tgz.path(), layer_path).map_err(RubyBuildpackError::RubyInstallError)?; + untar(tmp_ruby_tgz.path(), layer_path).map_err(RubyBuildpackError::RubyInstallError)?; - timer.done(); - - LayerResultBuilder::new(RubyInstallLayerMetadata { - stack: context.stack_id.clone(), - version: self.version.clone(), + LayerResultBuilder::new(self.metadata.clone()).build() }) - .build() } fn existing_layer_strategy( &self, - context: &BuildContext, + _context: &BuildContext, layer_data: &LayerData, ) -> Result { let old = &layer_data.content_metadata.metadata; - let now = RubyInstallLayerMetadata { - stack: context.stack_id.clone(), - version: self.version.clone(), - }; + let now = self.metadata.clone(); match cache_state(old.clone(), now) { Changed::Nothing(_version) => { - self.build_output.say("Using cached version"); + log_step("Using cached version"); Ok(ExistingLayerStrategy::Keep) } Changed::Stack(_old, _now) => { - self.build_output - .say_with_details("Clearing cache", "stack changed"); + log_step(format!("Clearing cache {}", fmt::details("stack changed"))); Ok(ExistingLayerStrategy::Recreate) } Changed::RubyVersion(_old, _now) => { - self.build_output - .say_with_details("Clearing cache", "ruby version changed"); + log_step(format!( + "Clearing cache {}", + fmt::details("ruby version changed") + )); Ok(ExistingLayerStrategy::Recreate) } diff --git a/buildpacks/ruby/src/main.rs b/buildpacks/ruby/src/main.rs index c5d2fad..ee5cc48 100644 --- a/buildpacks/ruby/src/main.rs +++ b/buildpacks/ruby/src/main.rs @@ -1,15 +1,20 @@ #![warn(unused_crate_dependencies)] #![warn(clippy::pedantic)] #![allow(clippy::module_name_repetitions)] -use crate::layers::metrics_agent_install::{MetricsAgentInstall, MetricsAgentInstallError}; -use crate::layers::{RubyInstallError, RubyInstallLayer}; -use crate::rake_task_detect::RakeError; -use commons::build_output; use commons::cache::CacheError; use commons::fun_run::CmdError; use commons::gemfile_lock::GemfileLock; +use commons::metadata_digest::MetadataDigest; +use commons::output::warn_later::WarnGuard; +#[allow(clippy::wildcard_imports)] +use commons::output::{build_log::*, fmt}; use core::str::FromStr; -use layers::{BundleDownloadLayer, BundleInstallLayer}; +use layers::{ + bundle_download_layer::{BundleDownloadLayer, BundleDownloadLayerMetadata}, + bundle_install_layer::{BundleInstallLayer, BundleInstallLayerMetadata}, + metrics_agent_install::{MetricsAgentInstall, MetricsAgentInstallError}, + ruby_install_layer::{RubyInstallError, RubyInstallLayer, RubyInstallLayerMetadata}, +}; use libcnb::build::{BuildContext, BuildResult, BuildResultBuilder}; use libcnb::data::build_plan::BuildPlanBuilder; use libcnb::data::launch::LaunchBuilder; @@ -19,7 +24,7 @@ use libcnb::generic::{GenericMetadata, GenericPlatform}; use libcnb::layer_env::Scope; use libcnb::Platform; use libcnb::{buildpack_main, Buildpack}; -use regex::Regex; +use std::io::stdout; mod gem_list; mod layers; @@ -66,110 +71,154 @@ impl Buildpack for RubyBuildpack { .build() } + #[allow(clippy::too_many_lines)] fn build(&self, context: BuildContext) -> libcnb::Result { - let build_duration = build_output::buildpack_name("Heroku Ruby Buildpack"); + let mut logger = BuildLog::new(stdout()).buildpack_name("Heroku Ruby Buildpack"); + let warn_later = WarnGuard::new(stdout()); // ## Set default environment let (mut env, store) = crate::steps::default_env(&context, &context.platform.env().clone())?; // Gather static information about project - let lockfile_contents = fs_err::read_to_string(context.app_dir.join("Gemfile.lock")) - .map_err(RubyBuildpackError::MissingGemfileLock)?; + let lockfile = context.app_dir.join("Gemfile.lock"); + let lockfile_contents = fs_err::read_to_string(&lockfile) + .map_err(|error| RubyBuildpackError::MissingGemfileLock(lockfile, error))?; let gemfile_lock = GemfileLock::from_str(&lockfile_contents).expect("Infallible"); let bundler_version = gemfile_lock.resolve_bundler("2.4.5"); let ruby_version = gemfile_lock.resolve_ruby("3.1.3"); // ## Install metrics agent - let section = build_output::section("Metrics agent"); - if lockfile_contents.contains("barnes") { - context.handle_layer( - layer_name!("metrics_agent"), - MetricsAgentInstall { section }, - )?; - } else { - section.say_with_details( - "Skipping install", - "`gem 'barnes'` not found in Gemfile.lock", - ); + (logger, env) = { + let section = logger.section("Metrics agent"); + if lockfile_contents.contains("barnes") { + let layer_data = context.handle_layer( + layer_name!("metrics_agent"), + MetricsAgentInstall { + _in_section: section.as_ref(), + }, + )?; + + ( + section.end_section(), + layer_data.env.apply(Scope::Build, &env), + ) + } else { + ( + section + .step(&format!( + "Skipping install ({barnes} gem not found)", + barnes = fmt::value("barnes") + )) + .end_section(), + env, + ) + } }; // ## Install executable ruby version - - env = { - let section = build_output::section(format!( + (logger, env) = { + let section = logger.section(&format!( "Ruby version {} from {}", - build_output::fmt::value(ruby_version.to_string()), - build_output::fmt::value(gemfile_lock.ruby_source()) + fmt::value(ruby_version.to_string()), + fmt::value(gemfile_lock.ruby_source()) )); let ruby_layer = context // .handle_layer( layer_name!("ruby"), RubyInstallLayer { - build_output: section, - version: ruby_version.clone(), + _in_section: section.as_ref(), + metadata: RubyInstallLayerMetadata { + stack: context.stack_id.clone(), + version: ruby_version.clone(), + }, }, )?; - ruby_layer.env.apply(Scope::Build, &env) + let env = ruby_layer.env.apply(Scope::Build, &env); + (section.end_section(), env) }; // ## Setup bundler - env = { - let section = build_output::section(format!( + (logger, env) = { + let section = logger.section(&format!( "Bundler version {} from {}", - build_output::fmt::value(bundler_version.to_string()), - build_output::fmt::value(gemfile_lock.bundler_source()) + fmt::value(bundler_version.to_string()), + fmt::value(gemfile_lock.bundler_source()) )); let download_bundler_layer = context.handle_layer( layer_name!("bundler"), BundleDownloadLayer { env: env.clone(), - version: bundler_version, - build_output: section, + metadata: BundleDownloadLayerMetadata { + version: bundler_version, + }, + _section_logger: section.as_ref(), }, )?; - download_bundler_layer.env.apply(Scope::Build, &env) + let env = download_bundler_layer.env.apply(Scope::Build, &env); + + (section.end_section(), env) }; // ## Bundle install - env = { - let section = build_output::section("Bundle install"); - + (logger, env) = { + let section = logger.section("Bundle install"); let bundle_install_layer = context.handle_layer( layer_name!("gems"), BundleInstallLayer { env: env.clone(), without: BundleWithout::new("development:test"), - ruby_version, - build_output: section, + _section_log: section.as_ref(), + metadata: BundleInstallLayerMetadata { + stack: context.stack_id.clone(), + ruby_version: ruby_version.clone(), + force_bundle_install_key: String::from( + crate::layers::bundle_install_layer::FORCE_BUNDLE_INSTALL_CACHE_KEY, + ), + digest: MetadataDigest::new_env_files( + &context.platform, + &[ + &context.app_dir.join("Gemfile"), + &context.app_dir.join("Gemfile.lock"), + ], + ) + .map_err(|error| match error { + commons::metadata_digest::DigestError::CannotReadFile(path, error) => { + RubyBuildpackError::BundleInstallDigestError(path, error) + } + })?, + }, }, )?; - bundle_install_layer.env.apply(Scope::Build, &env) + let env = bundle_install_layer.env.apply(Scope::Build, &env); + (section.end_section(), env) }; // ## Detect gems - let (gem_list, default_process) = { - let section = build_output::section("Setting default processes(es)"); - section.say("Detecting gems"); + let (mut logger, gem_list, default_process) = { + let section = logger.section("Setting default processes"); - let gem_list = gem_list::GemList::from_bundle_list(&env, §ion) + let gem_list = gem_list::GemList::from_bundle_list(&env, section.as_ref()) .map_err(RubyBuildpackError::GemListGetError)?; - let default_process = steps::get_default_process(§ion, &context, &gem_list); + let default_process = steps::get_default_process(section.as_ref(), &context, &gem_list); - (gem_list, default_process) + (section.end_section(), gem_list, default_process) }; // ## Assets install - - { - let section = build_output::section("Rake assets install"); - let rake_detect = crate::steps::detect_rake_tasks(§ion, &gem_list, &context, &env)?; + logger = { + let section = logger.section("Rake assets install"); + let rake_detect = + crate::steps::detect_rake_tasks(section.as_ref(), &gem_list, &context, &env)?; if let Some(rake_detect) = rake_detect { - crate::steps::rake_assets_install(§ion, &context, &env, &rake_detect)?; + crate::steps::rake_assets_install(section.as_ref(), &context, &env, &rake_detect)?; } + + section.end_section() }; - build_duration.done_timed(); + logger.finish_logging(); + warn_later.warn_now(); if let Some(default_process) = default_process { BuildResultBuilder::new() @@ -187,19 +236,19 @@ impl Buildpack for RubyBuildpack { } fn needs_java(gemfile_lock: &str) -> bool { - let java_regex = Regex::new(r"\(jruby ").expect("Internal Error: Invalid regex"); + let java_regex = regex::Regex::new(r"\(jruby ").expect("clippy"); java_regex.is_match(gemfile_lock) } #[derive(Debug)] pub(crate) enum RubyBuildpackError { - RakeDetectError(RakeError), - GemListGetError(gem_list::ListError), + RakeDetectError(CmdError), + GemListGetError(CmdError), RubyInstallError(RubyInstallError), MetricsAgentError(MetricsAgentInstallError), - MissingGemfileLock(std::io::Error), + MissingGemfileLock(std::path::PathBuf, std::io::Error), InAppDirCacheError(CacheError), - BundleInstallDigestError(commons::metadata_digest::DigestError), + BundleInstallDigestError(std::path::PathBuf, std::io::Error), BundleInstallCommandError(CmdError), RakeAssetsPrecompileFailed(CmdError), GemInstallBundlerCommandError(CmdError), diff --git a/buildpacks/ruby/src/rake_task_detect.rs b/buildpacks/ruby/src/rake_task_detect.rs index 94ae28e..1782bc5 100644 --- a/buildpacks/ruby/src/rake_task_detect.rs +++ b/buildpacks/ruby/src/rake_task_detect.rs @@ -1,10 +1,12 @@ -use commons::fun_run::{self, CmdError, CmdMapExt}; +use commons::output::{ + fmt, + section_log::{log_step_timed, SectionLogger}, +}; + +use commons::fun_run::{CmdError, CommandWithName}; use core::str::FromStr; -use regex::Regex; use std::{ffi::OsStr, process::Command}; -use crate::build_output::{RunCommand, Section}; - /// Run `rake -P` and parse output to show what rake tasks an application has /// /// ```rust,no_run @@ -19,54 +21,46 @@ pub struct RakeDetect { output: String, } -#[derive(thiserror::Error, Debug)] -pub enum RakeError { - #[error("Regex error: {0}")] - RegexError(#[from] regex::Error), - - #[error("Error detecting rake tasks: {0}")] - DashpCommandError(fun_run::CmdError), -} - impl RakeDetect { /// # Errors /// /// Will return `Err` if `bundle exec rake -p` command cannot be invoked by the operating system. pub fn from_rake_command, K: AsRef, V: AsRef>( - section: &Section, + _logger: &dyn SectionLogger, envs: T, error_on_failure: bool, - ) -> Result { - Command::new("bundle") - .args(["exec", "rake", "-P", "--trace"]) + ) -> Result { + let mut cmd = Command::new("bundle"); + cmd.args(["exec", "rake", "-P", "--trace"]) .env_clear() - .envs(envs) - .cmd_map(|cmd| { - section.run(RunCommand::silent(cmd)).or_else(|error| { - if error_on_failure { - Err(error) - } else { - match error { - CmdError::SystemError(_, _) => Err(error), - CmdError::NonZeroExitNotStreamed(_, output) - | CmdError::NonZeroExitAlreadyStreamed(_, output) => Ok(output), - } - } - }) - }) - .map_err(RakeError::DashpCommandError) - .and_then(|output| RakeDetect::from_str(&String::from_utf8_lossy(&output.stdout))) + .envs(envs); + + log_step_timed(format!("Running {}", fmt::command(cmd.name())), || { + cmd.named_output() + }) + .or_else(|error| { + if error_on_failure { + Err(error) + } else { + match error { + CmdError::SystemError(_, _) => Err(error), + CmdError::NonZeroExitNotStreamed(output) + | CmdError::NonZeroExitAlreadyStreamed(output) => Ok(output), + } + } + }) + .and_then(|output| RakeDetect::from_str(&output.stdout_lossy())) } #[must_use] pub fn has_task(&self, string: &str) -> bool { - let task_re = Regex::new(&format!("\\s{string}")).expect("Internal error with regex"); + let task_re = regex::Regex::new(&format!("\\s{string}")).expect("clippy"); task_re.is_match(&self.output) } } impl FromStr for RakeDetect { - type Err = RakeError; + type Err = CmdError; fn from_str(string: &str) -> Result { Ok(RakeDetect { diff --git a/buildpacks/ruby/src/steps/detect_rake_tasks.rs b/buildpacks/ruby/src/steps/detect_rake_tasks.rs index c9ad726..9712622 100644 --- a/buildpacks/ruby/src/steps/detect_rake_tasks.rs +++ b/buildpacks/ruby/src/steps/detect_rake_tasks.rs @@ -1,4 +1,8 @@ -use crate::build_output::{self, Section}; +use commons::output::{ + fmt::{self, HELP}, + section_log::{log_step, SectionLogger}, +}; + use crate::gem_list::GemList; use crate::rake_status::{check_rake_ready, RakeStatus}; use crate::rake_task_detect::RakeDetect; @@ -8,14 +12,14 @@ use libcnb::build::BuildContext; use libcnb::Env; pub(crate) fn detect_rake_tasks( - section: &Section, + logger: &dyn SectionLogger, gem_list: &GemList, context: &BuildContext, env: &Env, ) -> Result, RubyBuildpackError> { - let rake = build_output::fmt::value("rake"); - let gemfile = build_output::fmt::value("Gemfile"); - let rakefile = build_output::fmt::value("Rakefile"); + let rake = fmt::value("rake"); + let gemfile = fmt::value("Gemfile"); + let rakefile = fmt::value("Rakefile"); match check_rake_ready( &context.app_dir, @@ -23,45 +27,49 @@ pub(crate) fn detect_rake_tasks( [".sprockets-manifest-*.json", "manifest-*.json"], ) { RakeStatus::MissingRakeGem => { - section.say_with_details( - "Cannot run rake tasks", - format!("no {rake} gem in {gemfile}"), - ); + log_step(format!( + "Skipping rake tasks {}", + fmt::details(format!("no {rake} gem in {gemfile}")) + )); - let gem = build_output::fmt::value("gem 'rake'"); - section.help(format!("Add {gem} to your {gemfile} to enable")); + log_step(format!( + "{HELP} Add {gem} to your {gemfile} to enable", + gem = fmt::value("gem 'rake'") + )); Ok(None) } RakeStatus::MissingRakefile => { - section.say_with_details("Cannot run rake tasks", format!("no {rakefile}")); - section.help(format!("Add {rakefile} to your project to enable")); + log_step(format!( + "Skipping rake tasks {}", + fmt::details(format!("no {rakefile}")) + )); + log_step(format!("{HELP} Add {rakefile} to your project to enable",)); Ok(None) } RakeStatus::SkipManifestFound(paths) => { let files = paths .iter() - .map(|path| build_output::fmt::value(path.to_string_lossy())) + .map(|path| fmt::value(path.to_string_lossy())) .collect::>() .join(", "); - section.say_with_details( - "Skipping rake tasks", - format!("Manifest files found {files}"), - ); - section.help("Delete files to enable running rake tasks"); + log_step(format!( + "Skipping rake tasks {}", + fmt::details(format!("Manifest files found {files}")) + )); + log_step(format!("{HELP} Delete files to enable running rake tasks")); Ok(None) } RakeStatus::Ready(path) => { - let path = build_output::fmt::value(path.to_string_lossy()); - section.say_with_details( - "Rake detected", - format!("{rake} gem found, {rakefile} found at {path}"), - ); + log_step(format!( + "Detected rake ({rake} gem found, {rakefile} found at {path})", + path = fmt::value(path.to_string_lossy()) + )); - let rake_detect = RakeDetect::from_rake_command(section, env, true) + let rake_detect = RakeDetect::from_rake_command(logger, env, true) .map_err(RubyBuildpackError::RakeDetectError)?; Ok(Some(rake_detect)) diff --git a/buildpacks/ruby/src/steps/get_default_process.rs b/buildpacks/ruby/src/steps/get_default_process.rs index 4fa0265..8683411 100644 --- a/buildpacks/ruby/src/steps/get_default_process.rs +++ b/buildpacks/ruby/src/steps/get_default_process.rs @@ -1,6 +1,9 @@ -use crate::build_output::{self, Section}; use crate::gem_list::GemList; use crate::RubyBuildpack; +use commons::output::{ + fmt, + section_log::{log_step, SectionLogger}, +}; use libcnb::build::BuildContext; use libcnb::data::launch::Process; use libcnb::data::launch::ProcessBuilder; @@ -8,37 +11,37 @@ use libcnb::data::process_type; use std::path::Path; pub(crate) fn get_default_process( - section: &Section, + _logger: &dyn SectionLogger, context: &BuildContext, gem_list: &GemList, ) -> Option { - let config_ru = build_output::fmt::value("config.ru"); - let rails = build_output::fmt::value("rails"); - let rack = build_output::fmt::value("rack"); - let railties = build_output::fmt::value("railties"); + let config_ru = fmt::value("config.ru"); + let rails = fmt::value("rails"); + let rack = fmt::value("rack"); + let railties = fmt::value("railties"); match detect_web(gem_list, &context.app_dir) { WebProcess::Rails => { - section.say(format!("Detected rails app ({rails} gem)")); + log_step(format!("Detected rails app ({rails} gem found)")); Some(default_rails()) } WebProcess::RackWithConfigRU => { - section.say(format!( - "Detected rack app ({rack} gem and {config_ru} at root of application)" + log_step(format!( + "Detected rack app ({rack} gem found and {config_ru} at root of application)" )); Some(default_rack()) } WebProcess::RackMissingConfigRu => { - section.say(format!( - "Skipping default web process (detected {rack} gem but missing {config_ru} file" + log_step(format!( + "Skipping default web process ({rack} gem found but missing {config_ru} file)" )); None } WebProcess::Missing => { - section.say(format!( - "Skipping default web process (no web gems detected: {rails}, {railties}, {rack}" + log_step(format!( + "Skipping default web process ({rails}, {railties}, and {rack} not found)" )); None diff --git a/buildpacks/ruby/src/steps/rake_assets_install.rs b/buildpacks/ruby/src/steps/rake_assets_install.rs index 128ce3c..685b095 100644 --- a/buildpacks/ruby/src/steps/rake_assets_install.rs +++ b/buildpacks/ruby/src/steps/rake_assets_install.rs @@ -1,49 +1,47 @@ -use crate::build_output::{self, RunCommand, Section}; use crate::rake_task_detect::RakeDetect; use crate::RubyBuildpack; use crate::RubyBuildpackError; use commons::cache::{mib, AppCacheCollection, CacheConfig, KeepPath}; -use commons::fun_run::{self, CmdError, CmdMapExt}; +use commons::fun_run::{self, CmdError, CommandWithName}; +use commons::output::{ + fmt::{self, HELP}, + section_log::{log_step, log_step_stream, SectionLogger}, +}; use libcnb::build::BuildContext; use libcnb::Env; use std::process::Command; pub(crate) fn rake_assets_install( - section: &Section, + logger: &dyn SectionLogger, context: &BuildContext, env: &Env, rake_detect: &RakeDetect, ) -> Result<(), RubyBuildpackError> { let cases = asset_cases(rake_detect); - let rake_assets_precompile = build_output::fmt::value("rake assets:precompile"); - let rake_assets_clean = build_output::fmt::value("rake assets:clean"); - let rake_detect_cmd = build_output::fmt::value("bundle exec rake -P"); + let rake_assets_precompile = fmt::value("rake assets:precompile"); + let rake_assets_clean = fmt::value("rake assets:clean"); + let rake_detect_cmd = fmt::value("bundle exec rake -P"); match cases { AssetCases::None => { - section.say_with_details( - format!("Skipping {rake_assets_precompile}"), - format!("task not found via {rake_detect_cmd}"), - ); - section.help("Enable compiling assets by ensuring that task is present when running the detect command locally"); + log_step(format!( + "Skipping {rake_assets_precompile} {}", + fmt::details(format!("task not found via {rake_detect_cmd}")) + )); + log_step(format!("{HELP} Enable compiling assets by ensuring {rake_assets_precompile} is present when running the detect command locally")); } AssetCases::PrecompileOnly => { - section.say_with_details( - "Compiling assets without cache", - format!("clean task not found via {rake_detect_cmd}"), - ); - section.help(format!("Enable caching by ensuring {rake_assets_clean} is present when running the detect command locally")); + log_step(format!( + "Compiling assets without cache {}", + fmt::details(format!("Clean task not found via {rake_detect_cmd}")) + )); + log_step(format!("{HELP} Enable caching by ensuring {rake_assets_clean} is present when running the detect command locally")); - run_rake_assets_precompile(section, env) + run_rake_assets_precompile(env) .map_err(RubyBuildpackError::RakeAssetsPrecompileFailed)?; } AssetCases::PrecompileAndClean => { - section.say_with_details( - "Compiling assets with cache", - format!( - "detected {rake_assets_precompile} and {rake_assets_clean} via {rake_detect_cmd}" - ), - ); + log_step(format!("Compiling assets with cache {}", fmt::details(format!("detected {rake_assets_precompile} and {rake_assets_clean} via {rake_detect_cmd}")))); let cache_config = [ CacheConfig { @@ -59,12 +57,11 @@ pub(crate) fn rake_assets_install( ]; let cache = { - let section = section.clone(); - AppCacheCollection::new_and_load(context, cache_config, move |log| section.say(log)) + AppCacheCollection::new_and_load(context, cache_config, logger) .map_err(RubyBuildpackError::InAppDirCacheError)? }; - run_rake_assets_precompile_with_clean(section, env) + run_rake_assets_precompile_with_clean(env) .map_err(RubyBuildpackError::RakeAssetsPrecompileFailed)?; cache @@ -76,38 +73,39 @@ pub(crate) fn rake_assets_install( Ok(()) } -fn run_rake_assets_precompile(section: &Section, env: &Env) -> Result<(), CmdError> { - Command::new("bundle") - .args(["exec", "rake", "assets:precompile", "--trace"]) +fn run_rake_assets_precompile(env: &Env) -> Result<(), CmdError> { + let path_env = env.get("PATH").cloned(); + let mut cmd = Command::new("bundle"); + + cmd.args(["exec", "rake", "assets:precompile", "--trace"]) .env_clear() - .envs(env) - .cmd_map(|cmd| { - let path_env = env.get("PATH").cloned(); - section - .run(RunCommand::stream(cmd)) - .map_err(|error| fun_run::map_which_problem(error, cmd, path_env)) - })?; + .envs(env); + + log_step_stream(format!("Running {}", fmt::command(cmd.name())), |stream| { + cmd.stream_output(stream.io(), stream.io()) + .map_err(|error| fun_run::map_which_problem(error, &mut cmd, path_env)) + })?; Ok(()) } -fn run_rake_assets_precompile_with_clean(section: &Section, env: &Env) -> Result<(), CmdError> { - Command::new("bundle") - .args([ - "exec", - "rake", - "assets:precompile", - "assets:clean", - "--trace", - ]) - .env_clear() - .envs(env) - .cmd_map(|cmd| { - let path_env = env.get("PATH").cloned(); - section - .run(RunCommand::stream(cmd)) - .map_err(|error| fun_run::map_which_problem(error, cmd, path_env)) - })?; +fn run_rake_assets_precompile_with_clean(env: &Env) -> Result<(), CmdError> { + let path_env = env.get("PATH").cloned(); + let mut cmd = Command::new("bundle"); + cmd.args([ + "exec", + "rake", + "assets:precompile", + "assets:clean", + "--trace", + ]) + .env_clear() + .envs(env); + + log_step_stream(format!("Running {}", fmt::command(cmd.name())), |stream| { + cmd.stream_output(stream.io(), stream.io()) + }) + .map_err(|error| fun_run::map_which_problem(error, &mut cmd, path_env))?; Ok(()) } diff --git a/buildpacks/ruby/src/user_errors.rs b/buildpacks/ruby/src/user_errors.rs index 236bbda..d446574 100644 --- a/buildpacks/ruby/src/user_errors.rs +++ b/buildpacks/ruby/src/user_errors.rs @@ -1,125 +1,261 @@ -use indoc::formatdoc; +use std::process::Command; + +#[allow(clippy::wildcard_imports)] +use commons::output::{ + build_log::*, + fmt::{self, DEBUG_INFO}, +}; -use crate::{build_output::fmt::ErrorInfo, RubyBuildpackError}; +use crate::RubyBuildpackError; +use commons::fun_run::{CmdError, CommandWithName}; +use indoc::formatdoc; pub(crate) fn on_error(err: libcnb::Error) { + let log = BuildLog::new(std::io::stdout()).without_buildpack_name(); match cause(err) { - Cause::OurError(error) => log_our_error(error), - Cause::FrameworkError(error) => ErrorInfo::header_body_details( - "heroku/buildpack-ruby internal buildpack error", - formatdoc! {" - An unexpected internal error was reported by the framework used - by this buildpack. - - If the issue persists, consider opening an issue on the GitHub - repository. If you are unable to deploy to Heroku as a result - of this issue, consider opening a ticket for additional support. - "}, - error, - ) - .print(), + Cause::OurError(error) => log_our_error(log, error), + Cause::FrameworkError(error) => + log + .section(DEBUG_INFO) + .step(&error.to_string()) + .announce() + .error(&formatdoc! {" + Error: heroku/buildpack-ruby internal buildpack error + + The framework used by this buildpack encountered an unexpected error. + This type of error usually indicates there's nothing wrong with your application. + + If you can’t deploy to Heroku due to this issue please check the official Heroku + status page https://status.heroku.com/ to see if there is an ongoing incident. Once + all incidents have resolved please retry your build. + + If the issue persists, please try to reproduce the behavior locally using the `pack` + CLI. If you can reproduce the behavior locally and believe you've found a bug in the + buildpack or the framework please open an issue on the buildpack's GitHub repository. + "}), }; } -fn log_our_error(error: RubyBuildpackError) { +#[allow(clippy::too_many_lines)] +fn log_our_error(mut log: Box, error: RubyBuildpackError) { + let git_branch_url = + fmt::url("https://devcenter.heroku.com/articles/git#deploy-from-a-branch-besides-main"); + let ruby_versions_url = + fmt::url("https://devcenter.heroku.com/articles/ruby-support#ruby-versions"); + let rubygems_status_url = fmt::url("https://status.rubygems.org/"); + match error { - RubyBuildpackError::RakeDetectError(error) => ErrorInfo::header_body_details( - "Error detecting rake tasks", - formatdoc! {" - The Ruby buildpack uses rake task information from your application to guide - build logic. Without this information, the Ruby buildpack cannot continue. - "}, - error, - ) - .print(), - RubyBuildpackError::GemListGetError(error) => ErrorInfo::header_body_details( - "Error detecting dependencies", - formatdoc! {" - The Ruby buildpack uses dependency information from your application to - guide build logic. Without this information, the Ruby buildpack cannot - continue. - "}, - error, - ) - .print(), - RubyBuildpackError::RubyInstallError(error) => ErrorInfo::header_body_details( - "Error installing Ruby", - formatdoc! {" - Could not install the detected Ruby version. - "}, - error, - ) - .print(), - RubyBuildpackError::MissingGemfileLock(error) => ErrorInfo::header_body_details( - "Error: Gemfile.lock required", - formatdoc! {" - To deploy a Ruby application, a Gemfile.lock file is required in the - root of your application, but none was found. - - If you have a Gemfile.lock in your application, you may not have it - tracked in git, or you may be on a different branch. - "}, - error, - ) - .print(), - RubyBuildpackError::InAppDirCacheError(error) => ErrorInfo::header_body_details( - "Internal cache error", - formatdoc! {" - An internal error occurred while caching files. - "}, - error, - ) - .print(), - RubyBuildpackError::MetricsAgentError(error) => ErrorInfo::header_body_details( - formatdoc! { - "Could not install Statsd agent" - }, - formatdoc! { - "An error occured while downloading and installing the metrics agent - the buildpack cannot continue" - }, - error, - ) - .print(), - RubyBuildpackError::BundleInstallDigestError(error) => ErrorInfo::header_body_details( - "Could not generate digest", - formatdoc! {" - To provide the fastest possible install experience the Ruby buildpack - converts Gemfile and Gemfile.lock into a cryptographic digest to be - used in cache invalidation. - - While performing this process there was an unexpected internal error. - "}, - error, - ) - .print(), - RubyBuildpackError::BundleInstallCommandError(error) => ErrorInfo::header_body_details( - "Error installing bundler", - formatdoc! {" - Installation of bundler failed. Bundler is the package managment - library for Ruby. Bundler is needed to install your application's dependencies - listed in the Gemfile. - "}, - error, - ) - .print(), - RubyBuildpackError::RakeAssetsPrecompileFailed(error) => ErrorInfo::header_body_details( - "Asset compilation failed", - formatdoc! {" - An error occurred while compiling assets via rake command. - "}, - error, - ) - .print(), - RubyBuildpackError::GemInstallBundlerCommandError(error) => ErrorInfo::header_body_details( - "Installing gems failed", - formatdoc! {" - Could not install gems to the system via bundler. Gems are dependencies - your application listed in the Gemfile and resolved in the Gemfile.lock. - "}, - error, - ) - .print(), + RubyBuildpackError::MissingGemfileLock(path, error) => { + log = log + .section(&format!( + "Could not find {}, details:", + fmt::value(path.to_string_lossy()) + )) + .step(&error.to_string()) + .end_section(); + + if let Some(dir) = path.parent() { + log = debug_cmd( + log.section(&format!( + "{DEBUG_INFO} Contents of the {} directory", + fmt::value(dir.to_string_lossy()) + )), + Command::new("ls").args(["la", &dir.to_string_lossy()]), + ); + } + + log.announce().error(&formatdoc! {" + Error: `Gemfile.lock` not found + + A `Gemfile.lock` file is required and was not found in the root of your application. + + If you have a `Gemfile.lock` in your application, ensure it is tracked in Git and + that you’re pushing the correct branch. + + For more information: + {git_branch_url} + "}); + } + RubyBuildpackError::RubyInstallError(error) => { + // Future: + // - In the future use a manifest file to list if version is available on a different stack + // - In the future add a "did you mean" Levenshtein distance to see if they typoed like "3.6.0" when they meant "3.0.6" + log.section(DEBUG_INFO) + .step(&error.to_string()) + .announce() + .error(&formatdoc! {" + Error installing Ruby + + Could not install the detected Ruby version. Ensure that you're using a supported + ruby version and try again. + + Supported ruby versions: + {ruby_versions_url} + "}); + } + RubyBuildpackError::GemInstallBundlerCommandError(error) => { + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + log = debug_cmd(log.section(DEBUG_INFO), Command::new("gem").arg("env")); + + log.announce().error(&formatdoc! {" + Error installing bundler + + The ruby package managment tool, `bundler`, failed to install. Bundler is required + to install your application's dependencies listed in the `Gemfile`. + + Check the status page of RubyGems.org: + {rubygems_status_url} + + Once all incidents have been resolved, please retry your build. + "}); + } + RubyBuildpackError::BundleInstallCommandError(error) => { + // Future: + // - Grep error output for common things like using sqlite3, use classic buildpack + let local_command = local_command_debug(&error); + log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section() + .announce() + .error(&formatdoc! {" + Error installing your applications's dependencies + + Could not install gems to the system via bundler. Gems are dependencies + your application listed in the `Gemfile` and resolved in the `Gemfile.lock`. + + {local_command} + + If you believe that your application is correct, ensure all files are tracked in Git and + that you’re pushing the correct branch: + {git_branch_url} + + Use the information above to debug further. + "}); + } + RubyBuildpackError::BundleInstallDigestError(path, error) => { + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + if let Some(dir) = path.parent() { + log = debug_cmd( + log.section(&format!( + "{DEBUG_INFO} Contents of the {} directory", + fmt::value(dir.to_string_lossy()) + )), + Command::new("ls").args(["la", &dir.to_string_lossy()]), + ); + } + + log.announce().error(&formatdoc! {" + Error generating file digest + + An error occurred while generating a file digest. To provide the fastest possible + install experience, the Ruby buildpack converts your `Gemfile` and `Gemfile.lock` + into a digest to use in cache invalidation. + + Ensure that the permissions on the files in your application directory are correct and that + all symlinks correctly resolve. + + If you're unable to resolve this error, you can disable the the digest feature by + setting the environment variable: + + HEROKU_SKIP_BUNDLE_DIGEST=1 + "}); + } + RubyBuildpackError::RakeDetectError(error) => { + // Future: + // - Annotate with information on requiring test or development only gems in the Rakefile + let local_command = local_command_debug(&error); + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + log.announce().error(&formatdoc! {" + Error detecting rake tasks + + The Ruby buildpack uses rake task information from your application to guide + build logic. Without this information, the Ruby buildpack cannot continue. + + {local_command} + + Use the information above to debug further. + "}); + } + RubyBuildpackError::RakeAssetsPrecompileFailed(error) => { + let local_command = local_command_debug(&error); + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + log.announce().error(&formatdoc! {" + Error compiling assets + + An error occured while compiling assets via rake command. + + {local_command} + + Use the information above to debug further. + "}); + } + RubyBuildpackError::InAppDirCacheError(error) => { + // Future: + // - Separate between failures in layer dirs or in app dirs, if we can isolate to an app dir we could debug more + // to determine if there's bad permissions or bad file symlink + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + log.announce().error(&formatdoc! {" + Error caching frontend assets + + An error occurred while attempting to cache frontend assets, and the Ruby buildpack + cannot continue. + + Ensure that the permissions on the files in your application directory are correct and that + all symlinks correctly resolve. + "}); + } + RubyBuildpackError::GemListGetError(error) => { + log = log + .section(DEBUG_INFO) + .step(&error.to_string()) + .end_section(); + + log = debug_cmd(log.section(DEBUG_INFO), Command::new("gem").arg("env")); + + log = debug_cmd(log.section(DEBUG_INFO), Command::new("bundle").arg("env")); + + log.announce().error(&formatdoc! {" + Error detecting dependencies + + The Ruby buildpack requires information about your application’s dependencies to + complete the build. Without this information, the Ruby buildpack cannot continue. + + Use the information above to debug further. + "}); + } + RubyBuildpackError::MetricsAgentError(error) => { + log.section(DEBUG_INFO) + .step(&error.to_string()) + .end_section() + .announce() + .error(&formatdoc! {" + Error: Could not install Statsd agent + + An error occured while downloading and installing the metrics agent + the buildpack cannot continue. + "}); + } } } @@ -135,3 +271,49 @@ fn cause(err: libcnb::Error) -> Cause { err => Cause::FrameworkError(err), } } + +fn local_command_debug(error: &CmdError) -> String { + let cmd_name = replace_app_path_with_relative(fmt::command(error.name())); + + formatdoc! {" + Ensure you can run the following command locally with no errors before attempting another build: + + {cmd_name} + + "} +} + +fn replace_app_path_with_relative(contents: impl AsRef) -> String { + let app_path_re = regex::Regex::new("/workspace/").expect("Internal error: regex"); + + app_path_re.replace_all(contents.as_ref(), "./").to_string() +} + +fn debug_cmd(log: Box, command: &mut Command) -> Box { + let mut stream = log.step_timed_stream(&format!( + "Running debug command {}", + fmt::command(command.name()) + )); + + match command.stream_output(stream.io(), stream.io()) { + Ok(_) => stream.finish_timed_stream().end_section(), + Err(e) => stream + .finish_timed_stream() + .step(&e.to_string()) + .end_section(), + } +} + +#[cfg(test)] +mod test { + use super::*; + + #[test] + fn test_relative_path() { + let expected = r#"BUNDLE_DEPLOYMENT="1" BUNDLE_GEMFILE="./Gemfile" BUNDLE_WITHOUT="development:test" bundle install"#; + let actual = replace_app_path_with_relative( + r#"BUNDLE_DEPLOYMENT="1" BUNDLE_GEMFILE="/workspace/Gemfile" BUNDLE_WITHOUT="development:test" bundle install"#, + ); + assert_eq!(expected, &actual); + } +} diff --git a/buildpacks/ruby/tests/integration_test.rs b/buildpacks/ruby/tests/integration_test.rs index 89c2e68..3e64d2e 100644 --- a/buildpacks/ruby/tests/integration_test.rs +++ b/buildpacks/ruby/tests/integration_test.rs @@ -6,7 +6,6 @@ use libcnb_test::{ }; use std::thread; use std::time::{Duration, Instant}; -use thiserror::__private::AsDisplay; use ureq::Response; #[test] @@ -168,36 +167,28 @@ fn request_container( req.call().map_err(Box::new) } +fn time_bounded_retry(max_time: Duration, sleep_for: Duration, f: F) -> Result +where + F: Fn() -> Result, +{ + let start = Instant::now(); + + loop { + let result = f(); + if result.is_ok() || max_time <= (start.elapsed() + sleep_for) { + return result; + } + thread::sleep(sleep_for); + } +} + fn call_root_until_boot( container: &ContainerContext, port: u16, ) -> Result> { - let mut count = 0; - let max_time = 10.0_f64; // Seconds - let sleep = 0.1_f64; - - #[allow(clippy::cast_possible_truncation)] - let max_count = (max_time / sleep).floor() as i64; - let mut response = request_container(container, port, ""); - while count < max_count { - count += 1; - match response { - Err(ref box_e) => match box_e.as_ref() { - ureq::Error::Transport(e) => { - println!( - "Waiting for connection {}, retrying in {}", - e.as_display(), - sleep - ); - response = request_container(container, port, ""); - } - ureq::Error::Status(..) => break, - }, - _ => break, - } - - thread::sleep(frac_seconds(sleep)); - } + let response = time_bounded_retry(Duration::from_secs(10), frac_seconds(0.1_f64), || { + request_container(container, port, "") + }); println!( "{}\n{}", diff --git a/commons/Cargo.toml b/commons/Cargo.toml index 607f60a..ef70d57 100644 --- a/commons/Cargo.toml +++ b/commons/Cargo.toml @@ -4,6 +4,10 @@ version = "0.1.0" edition = "2021" publish = false +[[bin]] +name = "print_style_guide" +path = "bin/print_style_guide.rs" + [dependencies] byte-unit = "4" fancy-regex = "0.11" @@ -23,7 +27,12 @@ tempfile = "3" thiserror = "1" walkdir = "2" which_problem = "0.1" +ascii_table = { version = "4", features = ["color_codes"] } +const_format = "0.2" [dev-dependencies] +indoc = "2" filetime = "0.2" toml = "0.8" +libcnb-test = "0.15.0" +pretty_assertions = "1" diff --git a/commons/bin/print_style_guide.rs b/commons/bin/print_style_guide.rs new file mode 100644 index 0000000..53ccdec --- /dev/null +++ b/commons/bin/print_style_guide.rs @@ -0,0 +1,205 @@ +use ascii_table::AsciiTable; +use commons::fun_run::CommandWithName; +use commons::output::fmt::{self, DEBUG_INFO, HELP}; +use commons::output::{ + build_log::*, + section_log::{log_step, log_step_stream, log_step_timed}, +}; +use indoc::formatdoc; +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 {}", fmt::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 fmt 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![ + fmt::value("2.3.4"), + "fmt::value(\"2.3.f\")".to_string(), + "With versions, file names or other important values worth highlighting".to_string(), + ], + vec![ + fmt::url("https://www.schneems.com"), + "fmt::url(\"https://www.schneems.com\")".to_string(), + "With urls".to_string(), + ], + vec![ + fmt::command("bundle install"), + "fmt::command(command.name())".to_string(), + "With commands (alongside of `fun_run::CommandWithName`)".to_string(), + ], + vec![ + fmt::details("extra information"), + "fmt::details(\"extra information\")".to_string(), + "Add specific information at the end of a line i.e. 'Cache cleared (ruby version changed)'".to_string() + ], + vec![ + fmt::HELP.to_string(), + "fmt::HELP.to_string()".to_string(), + "A help prefix, use it in a step or section title".to_string() + ], + vec![ + fmt::DEBUG_INFO.to_string(), + "fmt::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/commons/src/build_output.rs b/commons/src/build_output.rs deleted file mode 100644 index 1bc6cb9..0000000 --- a/commons/src/build_output.rs +++ /dev/null @@ -1,717 +0,0 @@ -use crate::fun_run::{self, CmdError}; -use libherokubuildpack::write::{line_mapped, mappers::add_prefix}; -use std::io::Write; -use std::time::Instant; -use time::BuildpackDuration; - -pub use section::{RunCommand, Section}; - -/// Build with style -/// -/// ```rust,no_run -/// use commons::build_output::{self, RunCommand}; -/// use std::process::Command; -/// -/// // Announce your buildpack and time it -/// let timer = build_output::buildpack_name("Buildpack name"); -/// // Do stuff here -/// timer.done(); -/// -/// // Create section with a topic -/// let section = build_output::section("Ruby version"); -/// -/// // Output stuff in that section -/// section.say("Installing"); -/// section.say_with_details("Installing", "important stuff"); -/// -/// // Live stream a progress timer in that section -/// let mut timer = section.say_with_inline_timer("Installing with progress"); -/// // Do stuff here -/// timer.done(); -/// -/// // Decorate and format your output -/// let version = build_output::fmt::value("3.1.2"); -/// section.say(format!("Installing {version}")); -/// -/// // Run a command in that section with a variety of formatting options -/// // Stream the output to the user: -/// section -/// .run(RunCommand::stream( -/// Command::new("echo").args(&["hello world"]), -/// )) -/// .unwrap(); -/// -/// // Run a command after announcing it. Show a progress timer but don't stream the output : -/// section -/// .run(RunCommand::inline_progress( -/// Command::new("echo").args(&["hello world"]), -/// )) -/// .unwrap(); -/// -/// -/// // Run a command with no output: -/// section -/// .run(RunCommand::silent( -/// Command::new("echo").args(&["hello world"]), -/// )) -/// .unwrap(); -/// -/// // Control the display of the command being run: -/// section -/// .run(RunCommand::stream( -/// Command::new("bash").args(&["-c", "exec", "echo \"hello world\""]), -/// ).with_name("echo \"hello world\"")) -/// .unwrap(); -///``` - -mod time { - use super::{fmt, raw_inline_print}; - use std::thread::{self, JoinHandle}; - use std::time::Duration; - use std::time::Instant; - - /// Time the entire buildpack execution - pub struct BuildpackDuration { - pub(crate) start: Instant, - } - - impl BuildpackDuration { - /// Emit timing details with done block - pub fn done_timed(self) { - let time = human(&self.start.elapsed()); - let details = fmt::details(format!("finished in {time}")); - println!("- Done {details}"); - } - - /// Emit done block without timing details - #[allow(clippy::unused_self)] - pub fn done(self) { - println!("- Done"); - } - - /// Finish without announcing anything - #[allow(clippy::unused_self)] - pub fn done_silently(self) {} - } - - /// Handles outputing inline progress based on timing - /// - /// i.e. `- Installing ... (5.733s)` - /// - /// In this example the dashes roughly equate to seconds. - /// The moving output in the build indicates we're waiting for something - pub struct LiveTimingInline { - start: Instant, - stop_dots: std::sync::mpsc::Sender, - join_dots: Option>, - } - - impl Default for LiveTimingInline { - fn default() -> Self { - Self::new() - } - } - - impl LiveTimingInline { - #[must_use] - pub fn new() -> Self { - let (stop_dots, receiver) = std::sync::mpsc::channel(); - - let join_dots = thread::spawn(move || { - raw_inline_print(fmt::colorize(fmt::DEFAULT_DIM, " .")); - - loop { - let msg = receiver.recv_timeout(Duration::from_secs(1)); - raw_inline_print(fmt::colorize(fmt::DEFAULT_DIM, ".")); - - if msg.is_ok() { - raw_inline_print(fmt::colorize(fmt::DEFAULT_DIM, ". ")); - break; - } - } - }); - - Self { - stop_dots, - join_dots: Some(join_dots), - start: Instant::now(), - } - } - - fn stop_dots(&mut self) { - if let Some(handle) = self.join_dots.take() { - self.stop_dots.send(1).expect("Thread is not dead"); - handle.join().expect("Thread is joinable"); - } - } - - pub fn done(&mut self) { - self.stop_dots(); - let time = fmt::details(human(&self.start.elapsed())); - - println!("{time}"); - } - } - - // 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 - } - - 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()); - } - } -} - -// Helper for printing without newlines that auto-flushes stdout -fn raw_inline_print(contents: impl AsRef) { - let contents = contents.as_ref(); - print!("{contents}"); - std::io::stdout().flush().expect("Stdout is writable"); -} - -/// All work is done inside of a section. Advertize a section topic -pub fn section(topic: impl AsRef) -> section::Section { - let topic = String::from(topic.as_ref()); - println!("- {topic}"); - - section::Section { topic } -} - -/// Top level buildpack header -/// -/// Should only use once per buildpack -#[must_use] -pub fn buildpack_name(buildpack: impl AsRef) -> BuildpackDuration { - let header = fmt::header(buildpack.as_ref()); - println!("{header}"); - println!(); - - let start = Instant::now(); - BuildpackDuration { start } -} - -mod section { - use super::{ - add_prefix, fmt, fun_run, line_mapped, raw_inline_print, time, time::LiveTimingInline, - CmdError, Instant, - }; - use libherokubuildpack::command::CommandExt; - use std::process::{Command, Output}; - - const CMD_INDENT: &str = " "; - const SECTION_INDENT: &str = " "; - const SECTION_PREFIX: &str = " - "; - - #[derive(Debug, Clone, Eq, PartialEq)] - pub struct Section { - pub(crate) topic: String, - } - - impl Section { - /// Emit contents to the buid output with indentation - pub fn say(&self, contents: impl AsRef) { - let contents = contents.as_ref(); - println!("{SECTION_PREFIX}{contents}"); - } - - pub fn say_with_details(&self, contents: impl AsRef, details: impl AsRef) { - let contents = contents.as_ref(); - let details = fmt::details(details.as_ref()); - - println!("{SECTION_PREFIX}{contents} {details}"); - } - - /// Emit an indented help section with a "! Help:" prefix auto added - pub fn help(&self, contents: impl AsRef) { - let contents = fmt::help(contents); - - println!("{SECTION_INDENT}{contents}"); - } - - /// Start a time and emit a reson for it - /// - /// The timer will emit an inline progress meter until `LiveTimingInline::done` is called - /// on it. - #[must_use] - pub fn say_with_inline_timer(&self, reason: impl AsRef) -> time::LiveTimingInline { - let reason = reason.as_ref(); - raw_inline_print(format!("{SECTION_PREFIX}{reason}")); - - time::LiveTimingInline::new() - } - - /// Run a command with the given configuration and name - /// - /// # Errors - /// - /// Returns an error if the command status is non-zero or if the - /// system cannot run the command. - pub fn run(&self, run_command: RunCommand) -> Result { - match run_command.output { - OutputConfig::Stream | OutputConfig::StreamNoTiming => { - Self::stream_command(self, run_command) - } - OutputConfig::Silent => Self::silent_command(self, run_command), - OutputConfig::InlineProgress => Self::inline_progress_command(self, run_command), - } - } - - /// If someone wants to build their own command invocation and wants to match styles with this - /// command runner they'll need access to the prefix for consistent execution. - #[must_use] - pub fn cmd_stream_prefix() -> String { - String::from(CMD_INDENT) - } - - /// Run a command and output nothing to the screen - fn silent_command(_section: &Section, run_command: RunCommand) -> Result { - let RunCommand { - command, - name, - output: _, - } = run_command; - - command - .output() - .map_err(|error| fun_run::on_system_error(name.clone(), error)) - .and_then(|output| fun_run::nonzero_captured(name, output)) - } - - /// Run a command. Output command name, but don't stream the contents - fn inline_progress_command( - _section: &Section, - run_command: RunCommand, - ) -> Result { - let RunCommand { - command, - name, - output: _, - } = run_command; - let name = fmt::command(name); - - raw_inline_print(format!("{SECTION_PREFIX}Running {name}")); - - let mut start = LiveTimingInline::new(); - let output = command.output(); - let result = output - .map_err(|error| fun_run::on_system_error(name.clone(), error)) - .and_then(|output| fun_run::nonzero_captured(name, output)); - - start.done(); - - result - } - - /// Run a command. Output command name, and stream the contents - fn stream_command(section: &Section, run_command: RunCommand) -> Result { - let RunCommand { - command, - name, - output, - } = run_command; - let name = fmt::command(name); - - section.say(format!("Running {name}")); - println!(); // Weird output from prior stream adds indentation that's unwanted - - let start = Instant::now(); - let result = command - .output_and_write_streams( - line_mapped(std::io::stdout(), add_prefix(CMD_INDENT)), - line_mapped(std::io::stderr(), add_prefix(CMD_INDENT)), - ) - .map_err(|error| fun_run::on_system_error(name.clone(), error)) - .and_then(|output| fun_run::nonzero_streamed(name, output)); - - println!(); // Weird output from prior stream adds indentation that's unwanted - - let duration = start.elapsed(); - let time = fmt::details(time::human(&duration)); - match output { - OutputConfig::Stream => { - section.say(format!("Done {time}")); - } - OutputConfig::StreamNoTiming => section.say("Done {time}"), - OutputConfig::Silent | OutputConfig::InlineProgress => unreachable!(), - } - - result - } - } - - /// Specify how you want a command to be run by `Section::run` - pub struct RunCommand<'a> { - command: &'a mut Command, - name: String, - output: OutputConfig, - } - - impl<'a> RunCommand<'a> { - /// Generate a new `RunCommand` with a different name - #[must_use] - pub fn with_name(self, name: impl AsRef) -> Self { - let name = name.as_ref().to_string(); - let RunCommand { - command, - name: _, - output, - } = self; - - Self { - command, - name, - output, - } - } - - /// Announce and stream the output of a command - pub fn stream(command: &'a mut Command) -> Self { - let name = fun_run::display(command); - Self { - command, - name, - output: OutputConfig::Stream, - } - } - - /// Announce and stream the output of a command without timing information at the end - pub fn stream_without_timing(command: &'a mut Command) -> Self { - let name = fun_run::display(command); - Self { - command, - name, - output: OutputConfig::StreamNoTiming, - } - } - - /// Do not announce or stream output of a command - pub fn silent(command: &'a mut Command) -> Self { - let name = fun_run::display(command); - Self { - command, - name, - output: OutputConfig::Silent, - } - } - - /// Announce a command inline. Do not stream it's output. Emit inline progress timer. - pub fn inline_progress(command: &'a mut Command) -> Self { - let name = fun_run::display(command); - Self { - command, - name, - output: OutputConfig::InlineProgress, - } - } - } - - enum OutputConfig { - Stream, - StreamNoTiming, - Silent, - InlineProgress, - } -} - -pub mod fmt { - use indoc::formatdoc; - use std::fmt::Display; - - pub(crate) const RED: &str = "\x1B[0;31m"; - pub(crate) const YELLOW: &str = "\x1B[0;33m"; - pub(crate) const CYAN: &str = "\x1B[0;36m"; - - #[allow(dead_code)] - pub(crate) const PURPLE: &str = "\x1B[0;35m"; // magenta - - 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"; - - #[allow(dead_code)] - 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 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; - pub(crate) const WARNING_COLOR: &str = YELLOW; - - /// Used to decorate a command being run i.e. `bundle install` - #[must_use] - pub fn command(contents: impl AsRef) -> String { - value(colorize(COMMAND_COLOR, contents.as_ref())) - } - - /// Used to decorate a derived or user configured value - #[must_use] - pub fn value(contents: impl AsRef) -> String { - let contents = colorize(VALUE_COLOR, contents.as_ref()); - format!("`{contents}`") - } - - /// Used to decorate additional information - #[must_use] - pub fn details(contents: impl AsRef) -> String { - let contents = contents.as_ref(); - format!("({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}")) - } - - /// Used to standardize error/warning/important information - pub(crate) fn look_at_me( - color: &str, - noun: impl AsRef, - header: impl AsRef, - body: impl AsRef, - url: &Option, - ) -> String { - let noun = noun.as_ref(); - let header = header.as_ref(); - let body = help_url(body, url); - colorize( - color, - bangify(formatdoc! {" - {noun} {header} - - {body} - "}), - ) - } - - #[must_use] - pub(crate) fn help(contents: impl AsRef) -> String { - let contents = contents.as_ref(); - colorize(IMPORTANT_COLOR, bangify(format!("Help: {contents}"))) - } - - /// Holds the contents of an error - /// - /// Designed so that additional optional fields may be added later without - /// breaking compatability - #[derive(Debug, Clone, Default)] - pub struct ErrorInfo { - header: String, - body: String, - url: Option, - debug_details: Option, - } - - impl ErrorInfo { - pub fn header_body_details( - header: impl AsRef, - body: impl AsRef, - details: impl Display, - ) -> Self { - Self { - header: header.as_ref().to_string(), - body: body.as_ref().to_string(), - debug_details: Some(details.to_string()), - ..Default::default() - } - } - - pub fn print(&self) { - println!("{self}"); - } - } - - impl Display for ErrorInfo { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - f.write_str(error(self).as_str()) - } - } - - /// Need feedback on this interface - /// - /// Should it take fields or a struct - /// Struct is more robust to change but extra boilerplate - /// If the struct is always needed, this should perhaps be an associated function - #[must_use] - pub fn error(info: &ErrorInfo) -> String { - let ErrorInfo { - header, - body, - url, - debug_details, - } = info; - - let body = look_at_me(ERROR_COLOR, "ERROR:", header, body, url); - if let Some(details) = debug_details { - format!("{body}\n\nDebug information: {details}") - } else { - body - } - } - - /// Need feedback on this interface - /// - /// Should it have a dedicated struct like `ErrorInfo` or be a function? - /// Do we want to bundle warnings together and emit them at the end? (I think so, but it's out of current scope) - pub fn warning(header: impl AsRef, body: impl AsRef, url: &Option) -> String { - let header = header.as_ref(); - let body = body.as_ref(); - - look_at_me(WARNING_COLOR, "WARNING:", header, body, url) - } - - /// Need feedback on this interface - /// - /// Same questions as `warning` - pub fn important( - header: impl AsRef, - body: impl AsRef, - url: &Option, - ) -> String { - let header = header.as_ref(); - let body = body.as_ref(); - - look_at_me(IMPORTANT_COLOR, "", header, body, url) - } - - fn help_url(body: impl AsRef, url: &Option) -> String { - let body = body.as_ref(); - - if let Some(url) = url { - let url = colorize(URL_COLOR, url); - - formatdoc! {" - {body} - - For more information, refer to the following documentation: - {url} - "} - } else { - body.to_string() - } - } - - /// Helper method that adds a bang i.e. `!` before strings - fn bangify(body: impl AsRef) -> String { - body.as_ref() - .split('\n') - .map(|section| format!("! {section}")) - .collect::>() - .join("\n") - } - - /// 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') - .map(|section| section.replace(RESET, &format!("{RESET}{color}"))) // Handles nested color - .map(|section| format!("{color}{section}{RESET}")) // Clear after every newline - .map(|section| section.replace(&format!("{RESET}{color}{RESET}"), RESET)) // Reduce useless color - .map(|section| section.replace(&format!("{color}{color}"), color)) // Reduce useless color - .collect::>() - .join("\n") - } - - #[cfg(test)] - mod test { - use super::*; - - #[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); - } - } -} diff --git a/commons/src/cache/app_cache_collection.rs b/commons/src/cache/app_cache_collection.rs index 7bb9c42..f7d7d07 100644 --- a/commons/src/cache/app_cache_collection.rs +++ b/commons/src/cache/app_cache_collection.rs @@ -1,5 +1,7 @@ -use crate::cache::{AppCache, CacheConfig, CacheError, CacheState, FilesWithSize, PathState}; +use crate::cache::{AppCache, CacheConfig, CacheError, CacheState, PathState}; +use crate::output::{interface::SectionLogger, section_log as log}; use libcnb::{build::BuildContext, Buildpack}; +use std::fmt::Debug; /// App Cache Collection /// @@ -10,63 +12,13 @@ use libcnb::{build::BuildContext, Buildpack}; /// /// Default logging is provided for each operation. /// -/// ```rust -///# use libcnb::build::{BuildContext, BuildResult, BuildResultBuilder}; -///# use libcnb::data::launch::{LaunchBuilder, ProcessBuilder}; -///# use libcnb::data::process_type; -///# use libcnb::detect::{DetectContext, DetectResult, DetectResultBuilder}; -///# use libcnb::generic::{GenericError, GenericMetadata, GenericPlatform}; -///# use libcnb::{buildpack_main, Buildpack}; -///# use libcnb::data::layer_name; -///# use libcnb::data::layer::LayerName; -/// -///# pub(crate) struct HelloWorldBuildpack; -/// -/// use commons::cache::{AppCacheCollection, CacheConfig, KeepPath, mib}; -/// -///# impl Buildpack for HelloWorldBuildpack { -///# type Platform = GenericPlatform; -///# type Metadata = GenericMetadata; -///# type Error = GenericError; -/// -///# fn detect(&self, _context: DetectContext) -> libcnb::Result { -///# todo!() -///# } -/// -///# fn build(&self, context: BuildContext) -> libcnb::Result { -/// let cache = AppCacheCollection::new_and_load( -/// &context, -/// [ -/// CacheConfig { -/// path: context.app_dir.join("public").join("assets"), -/// limit: mib(100), -/// keep_path: KeepPath::Runtime, -/// }, -/// CacheConfig { -/// path: context.app_dir.join("tmp").join("cache").join("assets"), -/// limit: mib(100), -/// keep_path: KeepPath::BuildOnly, -/// }, -/// ], -/// |log| println!("{log}"), -/// ).unwrap(); -/// -/// // Do something worth caching here -/// -/// cache.save_and_clean().unwrap(); -/// -///# todo!() -///# } -///# } -/// -/// ``` #[derive(Debug)] -pub struct AppCacheCollection { +pub struct AppCacheCollection<'a> { + _log: &'a dyn SectionLogger, collection: Vec, - log_func: LogFunc, } -impl AppCacheCollection { +impl<'a> AppCacheCollection<'a> { /// Store multiple application paths in the cache /// /// # Errors @@ -77,15 +29,19 @@ impl AppCacheCollection { pub fn new_and_load( context: &BuildContext, config: impl IntoIterator, - logger: impl Fn(&str) + 'static, + log: &'a dyn SectionLogger, ) -> Result { - let log_func = LogFunc(Box::new(logger)); - let caches = config .into_iter() .map(|config| { AppCache::new_and_load(context, config).map(|store| { - log_load(&log_func, &store); + let path = store.path().display(); + + log::log_step(match store.cache_state() { + CacheState::NewEmpty => format!("Creating cache for {path}"), + CacheState::ExistsEmpty => format!("Loading (empty) cache for {path}"), + CacheState::ExistsWithContents => format!("Loading cache for {path}"), + }); store }) }) @@ -93,7 +49,7 @@ impl AppCacheCollection { Ok(Self { collection: caches, - log_func, + _log: log, }) } @@ -105,63 +61,28 @@ impl AppCacheCollection { /// be completed. For example due to file permissions. pub fn save_and_clean(&self) -> Result<(), CacheError> { for store in &self.collection { - self.log_save(store); + let path = store.path().display(); + + log::log_step(match store.path_state() { + PathState::Empty => format!("Storing cache for (empty) {path}"), + PathState::HasFiles => format!("Storing cache for {path}"), + }); if let Some(removed) = store.save_and_clean()? { - self.log_clean(store, &removed); + let path = store.path().display(); + let limit = store.limit(); + let removed_len = removed.files.len(); + let removed_size = removed.adjusted_bytes(); + + log::log_step(format!( + "Detected cache size exceeded (over {limit} limit by {removed_size}) for {path}" + )); + log::log_step(format!( + "Removed {removed_len} files from the cache for {path}", + )); } } Ok(()) } - - fn log_save(&self, store: &AppCache) { - let path = store.path().display(); - - self.log_func.log(&match store.path_state() { - PathState::Empty => format!("Storing cache for (empty) {path}"), - PathState::HasFiles => format!("Storing cache for {path}"), - }); - } - - fn log_clean(&self, store: &AppCache, removed: &FilesWithSize) { - let path = store.path().display(); - let limit = store.limit(); - let removed_len = removed.files.len(); - let removed_size = removed.adjusted_bytes(); - - self.log_func.log(&format!( - "Detected cache size exceeded (over {limit} limit by {removed_size}) for {path}" - )); - self.log_func.log(&format!( - "Removed {removed_len} files from the cache for {path}", - )); - } -} - -fn log_load(log_func: &LogFunc, store: &AppCache) { - let path = store.path().display(); - - log_func.log(&match store.cache_state() { - CacheState::NewEmpty => format!("Creating cache for {path}"), - CacheState::ExistsEmpty => format!("Loading (empty) cache for {path}"), - CacheState::ExistsWithContents => format!("Loading cache for {path}"), - }); -} - -/// Small wrapper for storing a logging function -/// -/// Implements: Debug. Does not implement Clone or Eq -struct LogFunc(Box); - -impl LogFunc { - fn log(&self, s: &str) { - (self).0(s); - } -} - -impl std::fmt::Debug for LogFunc { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - f.debug_tuple("LogFunc").field(&"Fn(&str)").finish() - } } diff --git a/commons/src/fun_run.rs b/commons/src/fun_run.rs index dfb78f2..cce1bbc 100644 --- a/commons/src/fun_run.rs +++ b/commons/src/fun_run.rs @@ -1,12 +1,18 @@ use lazy_static::lazy_static; +use libherokubuildpack::command::CommandExt; use std::ffi::OsString; +use std::io::Write; +use std::os::unix::process::ExitStatusExt; use std::process::Command; +use std::process::ExitStatus; use std::process::Output; use which_problem::Which; #[cfg(test)] use libherokubuildpack as _; +use crate::fun_run; + /// The `fun_run` module is designed to make running commands more fun for you /// and your users. /// @@ -31,30 +37,86 @@ use libherokubuildpack as _; /// /// - Fun(ctional) /// -/// The main interface is the `cmd_map` method, provided by the `CmdMapExt` trait extension. -/// Use this along with other fun methods to compose the command run of your dreams. +/// While the pieces can be composed functionally the real magic comes when you start mixing in the helper structs `NamedCommand`, `NamedOutput` and `CmdError`. +/// Together these will return a Result type that contains the associated name of the command just called: `Result`. /// /// Example: /// /// ```no_run -/// use commons::fun_run::{self, CmdMapExt}; -/// use libherokubuildpack::command::CommandExt; +/// use commons::fun_run::CommandWithName; /// use std::process::Command; /// use libcnb::Env; /// /// let env = Env::new(); /// -/// Command::new("bundle") +/// let result = Command::new("bundle") /// .args(["install"]) /// .envs(&env) -/// .cmd_map(|cmd| { -/// let name = fun_run::display(cmd); -/// eprintln!("\nRunning command:\n$ {name}"); -/// -/// cmd.output_and_write_streams(std::io::stdout(), std::io::stderr()) -/// .map_err(|error| fun_run::on_system_error(name.clone(), error)) -/// .and_then(|output| fun_run::nonzero_streamed(name.clone(), output)) -/// }).unwrap(); +/// .stream_output(std::io::stdout(), std::io::stderr()); +/// +/// match result { +/// Ok(output) => { +/// assert_eq!("bundle install", &output.name()) +/// }, +/// Err(varient) => { +/// assert_eq!("bundle install", &varient.name()) +/// } +/// } +/// ``` +/// +/// Change names as you see fit: +/// +/// ```no_run +/// use commons::fun_run::CommandWithName; +/// use std::process::Command; +/// use libcnb::Env; +/// +/// let env = Env::new(); +/// +/// let result = Command::new("gem") +/// .args(["install", "bundler", "-v", "2.4.1.7"]) +/// .envs(&env) +/// // Overwrites default command name which would include extra arguments +/// .named("gem install") +/// .stream_output(std::io::stdout(), std::io::stderr()); +/// +/// match result { +/// Ok(output) => { +/// assert_eq!("bundle install", &output.name()) +/// }, +/// Err(varient) => { +/// assert_eq!("bundle install", &varient.name()) +/// } +/// } +/// ``` +/// +/// Or include env vars: +/// +/// ```no_run +/// use commons::fun_run::{self, CommandWithName}; +/// use std::process::Command; +/// use libcnb::Env; +/// +/// let env = Env::new(); +/// +/// let result = Command::new("gem") +/// .args(["install", "bundler", "-v", "2.4.1.7"]) +/// .envs(&env) +/// // Overwrites default command name +/// .named_fn(|cmd| { +/// // Annotate command with GEM_HOME env var +/// fun_run::display_with_env_keys(cmd, &env, ["GEM_HOME"]) +/// }) +/// .stream_output(std::io::stdout(), std::io::stderr()); +/// +/// match result { +/// Ok(output) => { +/// assert_eq!("GEM_HOME=\"/usr/bin/local/.gems\" gem install bundler -v 2.4.1.7", &output.name()) +/// }, +/// Err(varient) => { +/// assert_eq!("GEM_HOME=\"/usr/bin/local/.gems\" gem install bundler -v 2.4.1.7", &varient.name()) +/// } +/// } /// ``` /// Allows for a functional-style flow when running a `Command` via @@ -78,6 +140,169 @@ where } } +/// Easilly convert command output into a result with names +/// +/// Associated function name is experimental and may change +pub trait ResultNameExt { + /// # Errors + /// + /// Returns a `CmdError::SystemError` if the original Result was `Err`. + fn with_name(self, name: impl AsRef) -> Result; +} + +/// Convert the value of `Command::output()` into `Result` +impl ResultNameExt for Result { + /// # Errors + /// + /// Returns a `CmdError::SystemError` if the original Result was `Err`. + fn with_name(self, name: impl AsRef) -> Result { + let name = name.as_ref(); + self.map_err(|io_error| CmdError::SystemError(name.to_string(), io_error)) + .map(|output| NamedOutput { + name: name.to_string(), + output, + }) + } +} + +pub trait CommandWithName { + fn name(&mut self) -> String; + fn mut_cmd(&mut self) -> &mut Command; + + fn named(&mut self, s: impl AsRef) -> NamedCommand<'_> { + let name = s.as_ref().to_string(); + let command = self.mut_cmd(); + NamedCommand { name, command } + } + + #[allow(clippy::needless_lifetimes)] + fn named_fn<'a>(&'a mut self, f: impl FnOnce(&mut Command) -> String) -> NamedCommand<'a> { + let cmd = self.mut_cmd(); + let name = f(cmd); + self.named(name) + } + + /// Runs the command without streaming + /// + /// # Errors + /// + /// Returns `CmdError::SystemError` if the system is unable to run the command. + /// Returns `CmdError::NonZeroExitNotStreamed` if the exit code is not zero. + fn named_output(&mut self) -> Result { + let name = self.name(); + self.mut_cmd() + .output() + .with_name(name) + .and_then(NamedOutput::nonzero_captured) + } + + /// Runs the command and streams to the given writers + /// + /// # Errors + /// + /// Returns `CmdError::SystemError` if the system is unable to run the command + /// Returns `CmdError::NonZeroExitAlreadyStreamed` if the exit code is not zero. + fn stream_output( + &mut self, + stdout_write: OW, + stderr_write: EW, + ) -> Result + where + OW: Write + Send, + EW: Write + Send, + { + let name = &self.name(); + self.mut_cmd() + .output_and_write_streams(stdout_write, stderr_write) + .with_name(name) + .and_then(NamedOutput::nonzero_streamed) + } +} + +impl CommandWithName for Command { + fn name(&mut self) -> String { + fun_run::display(self) + } + + fn mut_cmd(&mut self) -> &mut Command { + self + } +} + +/// It's a command, with a name +pub struct NamedCommand<'a> { + name: String, + command: &'a mut Command, +} + +impl CommandWithName for NamedCommand<'_> { + fn name(&mut self) -> String { + self.name.to_string() + } + + fn mut_cmd(&mut self) -> &mut Command { + self.command + } +} + +/// Holds a the `Output` of a command's execution along with it's "name" +/// +/// When paired with `CmdError` a `Result` will retain the +/// "name" of the command regardless of succss or failure. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct NamedOutput { + name: String, + output: Output, +} + +impl NamedOutput { + /// # Errors + /// + /// Returns an error if the status is not zero + pub fn nonzero_captured(self) -> Result { + nonzero_captured(self.name, self.output) + } + + /// # Errors + /// + /// Returns an error if the status is not zero + pub fn nonzero_streamed(self) -> Result { + nonzero_streamed(self.name, self.output) + } + + #[must_use] + pub fn status(&self) -> &ExitStatus { + &self.output.status + } + + #[must_use] + pub fn stdout_lossy(&self) -> String { + String::from_utf8_lossy(&self.output.stdout).to_string() + } + + #[must_use] + pub fn stderr_lossy(&self) -> String { + String::from_utf8_lossy(&self.output.stderr).to_string() + } + + #[must_use] + pub fn name(&self) -> String { + self.name.clone() + } +} + +impl AsRef for NamedOutput { + fn as_ref(&self) -> &Output { + &self.output + } +} + +impl From for Output { + fn from(value: NamedOutput) -> Self { + value.output + } +} + lazy_static! { // https://github.com/jimmycuadra/rust-shellwords/blob/d23b853a850ceec358a4137d5e520b067ddb7abc/src/lib.rs#L23 static ref QUOTE_ARG_RE: regex::Regex = regex::Regex::new(r"([^A-Za-z0-9_\-.,:/@\n])").expect("Internal error:"); @@ -174,9 +399,7 @@ pub fn map_which_problem( CmdError::SystemError(name, error) => { CmdError::SystemError(name, annotate_which_problem(error, cmd, path_env)) } - CmdError::NonZeroExitNotStreamed(_, _) | CmdError::NonZeroExitAlreadyStreamed(_, _) => { - error - } + CmdError::NonZeroExitNotStreamed(_) | CmdError::NonZeroExitAlreadyStreamed(_) => error, } } @@ -231,14 +454,69 @@ fn annotate_io_error(source: std::io::Error, annotation: String) -> std::io::Err #[derive(Debug, thiserror::Error)] #[allow(clippy::module_name_repetitions)] pub enum CmdError { - #[error("Could not run command command {0:?}. Details: {1}")] + #[error("Could not run command `{0}`. {1}")] SystemError(String, std::io::Error), - #[error("Command failed {0:?}.\nstatus: {}\nstdout: {}\nstderr: {}", .1.status, String::from_utf8_lossy(&.1.stdout), String::from_utf8_lossy(&.1.stderr))] - NonZeroExitNotStreamed(String, Output), + #[error("Command failed: `{cmd}`\nexit status: {status}\nstdout: {stdout}\nstderr: {stderr}", cmd = .0.name, status = .0.output.status.code().unwrap_or_else(|| 1), stdout = display_out_or_empty(&.0.output.stdout), stderr = display_out_or_empty(&.0.output.stderr))] + NonZeroExitNotStreamed(NamedOutput), + + #[error("Command failed: `{cmd}`\nexit status: {status}\nstdout: \nstderr: ", cmd = .0.name, status = .0.output.status.code().unwrap_or_else(|| 1))] + NonZeroExitAlreadyStreamed(NamedOutput), +} - #[error("Command failed {0:?}.\nstatus: {}\nstdout: see above\nstderr: see above", .1.status)] - NonZeroExitAlreadyStreamed(String, Output), +impl CmdError { + /// Returns a display representation of the command that failed + /// + /// Example: + /// + /// ```no_run + /// use commons::fun_run::{self, CmdMapExt, ResultNameExt}; + /// use std::process::Command; + /// + /// let result = Command::new("cat") + /// .arg("mouse.txt") + /// .cmd_map(|cmd| cmd.output().with_name(fun_run::display(cmd))); + /// + /// match result { + /// Ok(_) => todo!(), + /// Err(error) => assert_eq!(error.name().to_string(), "cat mouse.txt") + /// } + /// ``` + #[must_use] + pub fn name(&self) -> std::borrow::Cow<'_, str> { + match self { + CmdError::SystemError(name, _) => name.into(), + CmdError::NonZeroExitNotStreamed(out) | CmdError::NonZeroExitAlreadyStreamed(out) => { + out.name.as_str().into() + } + } + } +} + +impl From for NamedOutput { + fn from(value: CmdError) -> Self { + match value { + CmdError::SystemError(name, error) => NamedOutput { + name, + output: Output { + status: ExitStatus::from_raw(error.raw_os_error().unwrap_or(-1)), + stdout: Vec::new(), + stderr: error.to_string().into_bytes(), + }, + }, + CmdError::NonZeroExitNotStreamed(named) + | CmdError::NonZeroExitAlreadyStreamed(named) => named, + } + } +} + +fn display_out_or_empty(contents: &[u8]) -> String { + let contents = String::from_utf8_lossy(contents); + if contents.trim().is_empty() { + "".to_string() + } else { + contents.to_string() + } } /// Converts a `std::io::Error` into a `CmdError` which includes the formatted command name @@ -261,11 +539,15 @@ pub fn on_system_error(name: String, error: std::io::Error) -> CmdError { /// # Errors /// /// Returns Err when the `Output` status is non-zero -pub fn nonzero_streamed(name: String, output: Output) -> Result { +pub fn nonzero_streamed(name: String, output: impl Into) -> Result { + let output = output.into(); if output.status.success() { - Ok(output) + Ok(NamedOutput { name, output }) } else { - Err(CmdError::NonZeroExitAlreadyStreamed(name, output)) + Err(CmdError::NonZeroExitAlreadyStreamed(NamedOutput { + name, + output, + })) } } @@ -279,10 +561,14 @@ pub fn nonzero_streamed(name: String, output: Output) -> Result Result { +pub fn nonzero_captured(name: String, output: impl Into) -> Result { + let output = output.into(); if output.status.success() { - Ok(output) + Ok(NamedOutput { name, output }) } else { - Err(CmdError::NonZeroExitNotStreamed(name, output)) + Err(CmdError::NonZeroExitNotStreamed(NamedOutput { + name, + output, + })) } } diff --git a/commons/src/lib.rs b/commons/src/lib.rs index 0cef16e..f415d2c 100644 --- a/commons/src/lib.rs +++ b/commons/src/lib.rs @@ -1,7 +1,11 @@ #![warn(unused_crate_dependencies)] #![warn(clippy::pedantic)] -pub mod build_output; +// Used in both testing and printing the style guide +use indoc as _; +// Used in the style guide +use ascii_table as _; + pub mod cache; pub mod display; pub mod fun_run; @@ -9,5 +13,6 @@ pub mod gem_version; pub mod gemfile_lock; pub mod layer; pub mod metadata_digest; +pub mod output; mod err; diff --git a/commons/src/metadata_digest.rs b/commons/src/metadata_digest.rs index 24b6b01..3391e43 100644 --- a/commons/src/metadata_digest.rs +++ b/commons/src/metadata_digest.rs @@ -407,7 +407,9 @@ impl PathsDigest { fn add_paths(&mut self, paths: &[&Path]) -> Result<&mut Self, DigestError> { for path in paths { - let contents = fs_err::read_to_string(path).map_err(DigestError::CannotReadFile)?; + let contents = fs_err::read_to_string(path) + .map_err(|error| DigestError::CannotReadFile(path.to_path_buf(), error))?; + self.0 .insert(path.to_path_buf(), sha_from_string(&contents)); } @@ -418,8 +420,8 @@ impl PathsDigest { #[derive(thiserror::Error, Debug)] pub enum DigestError { - #[error("Attempted to read file for digest but cannot: {0}")] - CannotReadFile(std::io::Error), + #[error("Attempted to read file for digest but cannot: {1}")] + CannotReadFile(PathBuf, std::io::Error), } fn sha_from_env(env: &Env) -> ShaString { diff --git a/commons/src/output/background_timer.rs b/commons/src/output/background_timer.rs new file mode 100644 index 0000000..5fa7f45 --- /dev/null +++ b/commons/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().unwrap(); + 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/commons/src/output/build_log.rs b/commons/src/output/build_log.rs new file mode 100644 index 0000000..715beb6 --- /dev/null +++ b/commons/src/output/build_log.rs @@ -0,0 +1,707 @@ +use crate::output::background_timer::{start_timer, StopJoinGuard, StopTimer}; +use crate::output::fmt; +#[allow(clippy::wildcard_imports)] +pub use crate::output::interface::*; +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 commons::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", fmt::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, fmt::section(s)); + + Box::new(BuildLog { + io: self.io, + data: self.data, + state: PhantomData::, + }) + } + + fn finish_logging(mut self: Box) { + let elapsed = fmt::time::human(&self.data.started.elapsed()); + let details = fmt::details(format!("finished in {elapsed}")); + + writeln_now(&mut self.io, fmt::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, fmt::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 = fmt::step(format!("{s}{}", fmt::background_timer_start())); + let tick = fmt::background_timer_tick(); + let end = fmt::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, fmt::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, fmt::important(s.trim())); + writeln_now(&mut self.io, ""); + } + + fn log_warn_later_shared(&mut self, s: &str) { + let mut formatted = fmt::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, fmt::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(libherokubuildpack::write::line_mapped( + LockedWriter { + arc: self.arc_io.clone(), + }, + fmt::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 {}", + fmt::details(fmt::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, fmt::details(fmt::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::output::fmt::{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 libherokubuildpack::command::CommandExt; + 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(fmt::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(fmt::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/commons/src/output/fmt.rs b/commons/src/output/fmt.rs new file mode 100644 index 0000000..abe5c7a --- /dev/null +++ b/commons/src/output/fmt.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/commons/src/output/interface.rs b/commons/src/output/interface.rs new file mode 100644 index 0000000..46dc615 --- /dev/null +++ b/commons/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/commons/src/output/mod.rs b/commons/src/output/mod.rs new file mode 100644 index 0000000..705d12a --- /dev/null +++ b/commons/src/output/mod.rs @@ -0,0 +1,7 @@ +mod background_timer; +pub mod build_log; +pub mod fmt; +pub mod interface; +pub mod section_log; +mod util; +pub mod warn_later; diff --git a/commons/src/output/section_log.rs b/commons/src/output/section_log.rs new file mode 100644 index 0000000..a89fcf7 --- /dev/null +++ b/commons/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 commons::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 commons::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 commons::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 commons::fun_run::CommandWithName; +/// use commons::output::section_log::log_step_stream; +/// use commons::output::fmt; +/// +/// let mut cmd = std::process::Command::new("bundle"); +/// cmd.arg("install"); +/// +/// log_step_stream(format!("Running {}", fmt::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/commons/src/output/util.rs b/commons/src/output/util.rs new file mode 100644 index 0000000..8b49fa6 --- /dev/null +++ b/commons/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/commons/src/output/warn_later.rs b/commons/src/output/warn_later.rs new file mode 100644 index 0000000..b95b2be --- /dev/null +++ b/commons/src/output/warn_later.rs @@ -0,0 +1,352 @@ +use indoc::formatdoc; +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 commons::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 commons::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 commons::output::warn_later::WarnGuard; +/// use commons::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 commons::output::warn_later::WarnGuard; +/// use commons::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, + "{}", + formatdoc! {" + Cannot use warn_later unless a WarnGuard has been created + 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 commons::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 commons::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 commons::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()); + } +}