Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
* 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<Mutex<T: Write>>` 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<Mutex<T: Write>>` 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<Mutex<T: Write>>`. 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<SectionLoggerCell>` = note: the trait `Sync` is not implemented for `Mutex<SectionLoggerCell>` = note: required for `Arc<Mutex<SectionLoggerCell>>` 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 <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<Mutex<W>> 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<Mutex<W>> 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<dyn SectionLogger>) -> Box<dyn AnnounceLogger>`. 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<Self>, s: &str) -> Box<dyn Self> // 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<WarnGuard>`. 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<Mutex<W>>, 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<Mutex<W>>` 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<Self>, s: &str) -> Box<dyn StartedAnnounceLogger> { 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 <[email protected]> * Update commons/Cargo.toml Co-authored-by: Ed Morley <[email protected]> * Remove unneeded use newlines and wildcard imports * Fix spelling * Format the barnes gem name * Implement commented out "help" output --------- Co-authored-by: Manuel Fuchs <[email protected]> Co-authored-by: Ed Morley <[email protected]>
- Loading branch information
3 people
authored
Oct 30, 2023
1 parent
54845ff
commit 6d4029f