Update the logging interface #198

schneems · 2023-08-29T14:01:47Z

Supercedes #175

Malax · 2023-10-04T08:30:54Z

Do you want a thorough review on this or when you port this over to libherokubuildpack? Is that still the plan?

schneems · 2023-10-04T15:35:40Z

Do you want a thorough review on this or when you port this over to libherokubuildpack? Is that still the plan?

I think maybe give this a rough pass with an eye towards eventual integration, but I think we plan on a fairly exhaustive review on future libherokubuildpack work. Though if you both have the energy and feel the outcome could be better to really hammer both, then I say go for it. For the case of this specific PR the stakes are lower, so there's more room to experiment (saving that Colin is using my branch code so if we completely break an interface I want to at least warn him).

Malax · 2023-10-09T08:18:28Z

@schneems in this case, I'd say we rubber stamp this one and do a proper review on the libherokubuildpack one only. This is a huge PR and will take a lot of time to review and any change we make will break @colincasey.

schneems · 2023-10-09T15:29:41Z

Sounds good. Let's move forward with that strategy.

edmorley

This is a very quick skim review of mainly the non-Rust parts, since at +3,403 −1,507 this PR is too large to properly review - particularly since it mixes new APIs, error message content changes (as in the copy), CI changes etc.

buildpacks/ruby/CHANGELOG.md

commons/Cargo.toml

buildpacks/ruby/src/steps/detect_rake_tasks.rs

buildpacks/ruby/src/gem_list.rs

edmorley · 2023-10-19T12:03:31Z

@schneems Is this ready for merge?

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).

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).

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.

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.

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

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) ```

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`) ```

The output of gem install bundler is an implementation detail and is not needed. Use the more compact timer format instead.

Co-authored-by: Ed Morley <[email protected]>

## heroku/ruby ### Fixed - Update build logging style (#198) Co-authored-by: heroku-linguist[bot] <136119646+heroku-linguist[bot]@users.noreply.github.com>

schneems force-pushed the schneems/logging-state-machine-continued branch 11 times, most recently from 45190ce to 2b56182 Compare September 6, 2023 16:04

schneems force-pushed the schneems/logging-state-machine-continued branch 2 times, most recently from 34ea214 to 02758b4 Compare September 26, 2023 19:42

schneems force-pushed the schneems/logging-state-machine-continued branch 2 times, most recently from dda57de to 64c7e62 Compare October 3, 2023 21:11

schneems marked this pull request as ready for review October 3, 2023 21:20

schneems requested a review from a team as a code owner October 3, 2023 21:20

schneems force-pushed the schneems/logging-state-machine-continued branch 2 times, most recently from 1e866f6 to a97dec6 Compare October 6, 2023 17:31

edmorley approved these changes Oct 9, 2023

View reviewed changes

schneems force-pushed the schneems/logging-state-machine-continued branch from 0ebcbe9 to 7c85b5e Compare October 11, 2023 16:48

Malax and others added 4 commits October 30, 2023 09:20

WIP

1024fa3

WIP scoped thread experiment

4b3da91

WIP non-scopped-background logger

93aad71

schneems and others added 21 commits October 30, 2023 09:26

Update rust cache

9726acf

Fix function name

cd105e0

Fix command output in style guide

4cbec7f

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.

Update metrics buildpack to use new build output

a937fff

Clean up

d2834db

Clean up retry logic

8766545

Rust 1.73.0 clippy updates

13736a7

Update build output

5109be8

Re-run build to demonstrate cached output

6d16451

Reduce gem install bundler output

b5245dc

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

14e412e

Apply suggestions from code review

c3909b3

Co-authored-by: Ed Morley <[email protected]>

Update commons/Cargo.toml

2116bc2

Co-authored-by: Ed Morley <[email protected]>

Remove unneeded use newlines and wildcard imports

362a9c4

Fix spelling

de09250

Format the barnes gem name

ae799db

schneems force-pushed the schneems/logging-state-machine-continued branch from bf253a1 to d645702 Compare October 30, 2023 14:36

schneems changed the title ~~Updated logging interface~~ Update the logging interface Oct 30, 2023

Implement commented out "help" output

b3ccd76

schneems force-pushed the schneems/logging-state-machine-continued branch from d645702 to b3ccd76 Compare October 30, 2023 15:03

schneems merged commit 6d4029f into main Oct 30, 2023
6 checks passed

schneems deleted the schneems/logging-state-machine-continued branch October 30, 2023 15:11

heroku-linguist bot mentioned this pull request Oct 31, 2023

Prepare release v2.1.2 #228

Merged

heroku-linguist bot added a commit that referenced this pull request Oct 31, 2023

Prepare release v2.1.2 (#228)

4f514f6

## heroku/ruby ### Fixed - Update build logging style (#198) Co-authored-by: heroku-linguist[bot] <136119646+heroku-linguist[bot]@users.noreply.github.com>

heroku-linguist bot mentioned this pull request Oct 31, 2023

Update heroku/buildpacks-ruby to v2.1.2 heroku/cnb-builder-images#430

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Update the logging interface #198

Update the logging interface #198

schneems commented Aug 29, 2023

Malax commented Oct 4, 2023

schneems commented Oct 4, 2023

Malax commented Oct 9, 2023

schneems commented Oct 9, 2023

edmorley left a comment

edmorley commented Oct 19, 2023

Update the logging interface #198

Update the logging interface #198

Conversation

schneems commented Aug 29, 2023

Malax commented Oct 4, 2023

schneems commented Oct 4, 2023

Malax commented Oct 9, 2023

schneems commented Oct 9, 2023

edmorley left a comment

Choose a reason for hiding this comment

edmorley commented Oct 19, 2023