Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

pkg: simplify the display logs #10662

Merged
merged 1 commit into from
Jul 2, 2024
Merged

Conversation

maiste
Copy link
Collaborator

@maiste maiste commented Jun 20, 2024

Hi,
This PR is an attempt to make the toolchain logs less verbose. As the packages are evaluated as common rules, they printed a lot of lots. To overcome such behavior, the idea is to redirect the error logs into a file and print them in case of errors.

This PR is structured in 3 parts:

  1. A modification of the User_message module to embedded headers. This information is printed before any other logs. It allows displaying the name of the package or a piece of information to give a bit of context. Maybe, this part is too much for this PR. I can either extract it or remove it.
  2. Propagate the information such as the package name and the location to the function in charge of handling it.
  3. Provide a Output module to sink the error logs into a file and display them as : Error if it fails and, warning if the command succeeds, but in verbose mode.

⚠️ I left the feature flags turn to true for the review, but it might need to be removed before merging.

Note that I'm not award of most of the functionalities provided by the dune helper modules (Stdune, User_message, etc). So, feel free to suggest better implementation if it can improve the readability and fit better in the dune codebase! 🙏

Closes tarides/team-build-system#30

@emillon
Copy link
Collaborator

emillon commented Jun 21, 2024

Thanks. It's good that you managed to use the existing process code to do this.
In terms of design, the most important thing to address is whether we can implement that without adding headers in User_message. If that's not possible, we could try to share the "add a message before" logic with the "Context:" message added in #10414. My impression is that it could be implemented by prepending a paragraph.
For the general state of the PR, it will be useful to add tests for that. I don't have a great deal of experience with testing pkg code, but I think we have some helpers for that - @Leonidas-from-XIV should be able to help you. This will be useful to make sure that the feature keeps working as we're iterating on it.
I'll add short remarks on the implem.

@@ -226,13 +228,24 @@ let pp { loc; paragraphs; hints; annots = _ } =
(Pp.textf "File %S, %s, characters %d-%d:" start.pos_fname lnum start_c stop_c))
:: paragraphs
in
let paragraphs = List.append headers paragraphs in
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

does that yield to double printing of headers in some cases?

Copy link
Collaborator Author

@maiste maiste Jun 21, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It works the same as with the loc argument (heavily inspired). It means if someone executes the print_headers and the then uses pp, it will print it twice, yes.

However, this is exactly what could happen with loc as the Dune_console print the loc before calling User_message.print too (here). If you stick with pp or Console.print_user_message you won't have any duplication.

Pp.vbox (Pp.concat_map paragraphs ~sep:Pp.nop ~f:(fun pp -> Pp.seq pp Pp.cut))
;;

let print ?(config = Print_config.default) t =
Ansi_color.print (Pp.map_tags (pp t) ~f:config)
;;

let print_headers ?(config = Print_config.default) t =
let headers = Pp.concat_map t.headers ~sep:Pp.nop ~f:(fun pp -> Pp.seq pp Pp.cut) in
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pp.nop is the default value of ~sep (here and below)

src/dune_pkg/feature_flags.ml Outdated Show resolved Hide resolved
Comment on lines 632 to 633
: ?accepted_exit_codes:int Predicate.t
-> ?pkg_name:Dune_lang.Package_name.t
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we avoid optional arguments in new code - you can make accepted_exit_codes a labelled argument and pkg_name an option.

raise (User_error.E msg)
| true, Display.Verbose ->
let error = read t in
if has_output error
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
if has_output error
if not (String.is_empty error)

Comment on lines 655 to 656
let v ?(accepted_exit_codes = exit_code_zero) ?pkg_name suffix =
let fn = Temp.create File ~prefix ~suffix in
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we can improve the resource management here:

  • v kinds of sound like a constructor (we tend to use the create name for this), but it's actually opening a file.
  • if you can restructure that to a "context manager" this will be easier to reason about. something like val with_ : ?accepted_exit_codes -> ?pkg_name -> string -> f:(t -> 'a) -> 'a, a bit like In_channel.with_open. that way you don't have to deal with state, close etc.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • Yes, the v is an old Irmin habits...
  • It would make the code much simpler! Thanks

content
| Closed ->
raise
(User_error.E
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This part is likely to go away but we prefer Code_error.raise for this kind of defensive check

| Some pkg_name ->
let pkg_name = Dune_pkg.Package_name.to_string pkg_name in
Pp.(
tag report_style (text "<><><>")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no need to mimic what opam is doing here. this clutters output and is less accessible than just printing the error message.

@maiste
Copy link
Collaborator Author

maiste commented Jun 21, 2024

Thanks, the context argument is exactly what I would have need to achieve the headers part: I can totally fetch the Context in this branch to use it! 👍

However, Context does not seem to cover the case where you want to print information using Console.print_user_message with a location (which I need to use here). If you take a look at here, you can see it will always print the location pointer before the context as they won't do the print_header before. If this something readable when the print is related to the same project, it is not when you are building multiple packages (because of the toolchain part). It echoes with your comment:

no need to mimic what opam is doing here. this clutters output and is less accessible than just printing the error message.

IMHO, we need a kind of separation between the parsed packages because otherwise users might struggle to parse the logs. I can suggest something lighter like [<package_name>] or Context: Package <package_name> 🤷‍♂️ WDYT?

Few questions about the tests:

  • Is there a way to test on package that we know would fail forever?
  • If I move the feature flag to false, we won't be able to test the feature again because it requires them to be on. Could we add a sed or any text transformation to turn the false to true in these tests? Or is it something we want to avoid?

@emillon
Copy link
Collaborator

emillon commented Jun 21, 2024

Let me clarify a bit what I mean:

  • the first thing to do is to add tests for this. this way, we can discuss concretely about how the messages look
  • this feature, as I understand it, is not strictly related to toolchains, is it? it's about suppressing outputs when building packages? (if I misunderstood, please correct me - this changes the constraints)
    • if that's indeed a pkg-generic feature, you can use the existing testing mechanisms for pkg rules. we don't refer to existing packages in the tests, but we'd define a package that fails. I didn't find a test that does exactly that, but for example curl-not-installed.t attempts to build a package without curl installed and shows how it fails.
  • the context argument from Show the context name for errors happening in "alt" contexts #10414 means a Context.t, not a general "context" in the english sense. so you can't reuse it verbatim, but my point was that if we go that route you would be able to remove context in favor of a header. but let's first see if we can get rid of this header mechanism altogether.

@maiste
Copy link
Collaborator Author

maiste commented Jun 21, 2024

Thanks for the clarifications! 🙏

the first thing to do is to add tests for this. this way, we can discuss concretely about how the messages look

You are totally right. I'll add some of the corrections and add the tests then to help with the discussion.

this feature, as I understand it, is not strictly related to toolchains, is it? it's about suppressing outputs when building packages? (if I misunderstood, please correct me - this changes the constraints)

Sorry, my mistake: I still confuse the toolchain part and the packages part 😅 It's about suppressing the logs when building packages when there are no error, display only errors if we are in non-verbose and displaying all of them (warning in this case) when we are in verbose mode.

the context argument from #10414 means a Context.t

I'm not sure to fully understand the point here. In the PR you linked, it seems that it's using string option not Context.t.

To be fair, the headers part is only related to "how the messages look". If multiple packages fail, you have many errors, and it's hard to "humanly parse" displayed errors. Maybe this is not something that should land in this PR: this one could only be about printing logs in case of error or verbose mode and not care about the error style. Another PR could be more about refactoring the styling part.

@emillon
Copy link
Collaborator

emillon commented Jun 21, 2024

I'm not sure to fully understand the point here. In the PR you linked, it seems that it's using string option not Context.t.

that's to avoid dependency cycles, this is indeed a context name.

Copy link
Collaborator

@Leonidas-from-XIV Leonidas-from-XIV left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a good starting point! Happy to see it land soon.

I am a bit torn on including Loc.t as a value into the Spec. Usually we deal with them by having Loc.t * 'a types where 'a is the value the Loc.t is related to. I've looked at some other action specs and the other Specs don't include Locs, maybe someone can pitch in how to do that in the best way?

}

let prefix = "dune-pkg"
let exit_code_zero = Predicate.create (fun x -> x = 0)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can also use Int.equal 0 here.


type t =
{ pkg_name : Dune_pkg.Package_name.t option
; fn : Dpath.t
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fn is a bit of a poor name, as it reminds me more of "function" than filename.

@@ -652,7 +759,7 @@ module Run_with_path = struct

let is_useful_to ~memoize:_ = true

let encode { prog; args; ocamlfind_destdir } path _ : Dune_lang.t =
let encode { prog; args; ocamlfind_destdir; _ } path _ : Dune_lang.t =
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would suggest to specifically state the arguments that are being _'ed in such cases; otherwise you opt out of useful compiler errors that will tell you that you haven't dealt with an argument. Even if the case you have now might be legit, it will make it harder for future modifications.

(But in any case I believe pkg_name should also be encoded)

@maiste maiste changed the base branch from toolchains to main June 21, 2024 13:20
@maiste maiste removed the request for review from christinerose June 21, 2024 13:20
Copy link
Collaborator

@Leonidas-from-XIV Leonidas-from-XIV left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking of this and this is not a blocker but I thought it could be nice to have. But it can happen in a future PR as well.

src/dune_rules/pkg_rules.ml Show resolved Hide resolved
;;
end

let action prog args ~ocamlfind_destdir =
let action ~loc ?pkg_name prog args ~ocamlfind_destdir =
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No optional arguments please

@rgrinberg
Copy link
Member

If this PR is adding a file that isn't a target of a rule, what prevents the file from being deleted by dune in subsequent runs during stale artifact deletion?

@rgrinberg
Copy link
Member

A modification of the User_message module to embedded headers. This information is printed before any other logs. It allows displaying the name of the package or a piece of information to give a bit of context. Maybe, this part is too much for this PR. I can either extract it or remove it.

I would suggest that you try to accomplish what your PR needs without this change. Such headers are not transmitted through RPC nor are they interpreted by any of the editors. This makes our editor integration incomplete. It seems like a rather general feature, but I can't find a use for it anywhere else in the codebase.

@maiste
Copy link
Collaborator Author

maiste commented Jun 24, 2024

Hi @rgrinberg,
Thanks for the feedback!

If this PR is adding a file that isn't a target of a rule, what prevents the file from being deleted by dune in subsequent runs during stale artifact deletion?

The file is added temporary to get all the error logs of one process in the same file and avoid interleaving. Consequently, it is deleted as soon as the process finishes.

I would suggest that you try to accomplish what your PR needs without this change. Such headers are not transmitted through RPC nor are they interpreted by any of the editors. This makes our editor integration incomplete. It seems like a rather general feature, but I can't find a use for it anywhere else in the codebase.

Yes, I understand and agree with you! I'm wondering if the ~prefix or the ~context could be used to display more information about the package where the error occurred, and if it would work with dune rpc? Otherwise, I won't display a context about the package where it happens.

@maiste maiste force-pushed the logs/clean-logs-process branch 3 times, most recently from b3c4ffb to 63c8b7b Compare June 24, 2024 15:24
@maiste
Copy link
Collaborator Author

maiste commented Jun 24, 2024

I removed the headers related parts to make this PR more atomic. @emillon There is now a cram test to ensure the mechanism would be broken on purpose. @Leonidas-from-XIV, I followed your suggestion and added the location in the type as a tuple, as it's done everywhere.

It should be much simpler to review now, as it temporarily redirects the errors in a file and displays them or not, depending on the result of the command.

let pp_pkg =
let pkg_name = Dune_pkg.Package_name.to_string (fst t.pkg) in
if is_critical
then Pp.textf "Package %s fails to build" pkg_name
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
then Pp.textf "Package %s fails to build" pkg_name
then Pp.textf "Package %s failed to build" pkg_name

let pkg_name = Dune_pkg.Package_name.to_string (fst t.pkg) in
if is_critical
then Pp.textf "Package %s fails to build" pkg_name
else Pp.textf "Package %s prints some errors" pkg_name
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These are not necessarily errors, right?

Suggested change
else Pp.textf "Package %s prints some errors" pkg_name
else Pp.textf "Package %s output" pkg_name

if not (String.is_empty error)
then (
let msg = error_msg ~is_critical:false t error in
Console.print_user_message msg)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure what the difference is but I think we often use

Suggested change
Console.print_user_message msg)
User_message.print msg)

result
;;

let error_msg ~is_critical t error =
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the is_critical bool is a bit weird, I wonder if that would be clearer to pass the message instead

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This issue is that in one case it's a Warning and in another one it's an Error. We need to stick to the behaviour in Process and raise only on critical error. I can change it by adding a kind instead of is_critical using variant.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah ok I missed that part. My main issue was the critical bit, indeed. What you're suggesting is fine by me, but as a final suggestion, maybe we can use User_warning.emit and the is_error flag, with just Logs for package X as message in both cases. I wonder if that would be enough?

Copy link
Collaborator Author

@maiste maiste Jun 25, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As it would display Error and Warning in front of the message, I think this is enough for now 👍

Copy link
Collaborator

@Leonidas-from-XIV Leonidas-from-XIV left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This PR breaks some other tests (which relied on the fact that the output was always printed). Could you go and fix them? I assume that requires passing --verbose to where this is necessary.

> (build
> (progn
> (run echo "Success!")
> (run true)))
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not necessary, echo will already return 0.

@maiste
Copy link
Collaborator Author

maiste commented Jun 25, 2024

@Leonidas-from-XIV, I'm not sure about the path I should take with this. Indeed, if I add a verbose flag, the tests would pass, but the logging result is pretty big... Is it OK to do so?

@Leonidas-from-XIV
Copy link
Collaborator

You could prefix the tests to output a specific output and do dune build | grep <THAT-PREFIX>. Alternatively, make the tests output their output to a file that's getting installed and then cat that file to show the result. The latter might be a tiny bit cleaner but also a tiny bit more involved.

Copy link
Member

@rgrinberg rgrinberg left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll give others a chance to review. This is good to go from me.

@rgrinberg
Copy link
Member

To make it easy to fix the tests, you could add restore the old behavior with INSIDE_DUNE or another variable.

@maiste
Copy link
Collaborator Author

maiste commented Jun 26, 2024

Thanks, @rgrinberg!
For the tests, I'm updating them to use a file as @Leonidas-from-XIV suggested. It would make the ones concerned more resilient to output changes. Indeed, the goal of the tests that currently break is to test the behavior, not the output. This way, the test I added would ensure the output stay consistent and the other ones the behavior.

@maiste maiste force-pushed the logs/clean-logs-process branch 2 times, most recently from e55994a to 7a01a8e Compare June 27, 2024 09:18
Copy link
Collaborator

@christinerose christinerose left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Changed make to make, but if there is a different way to do that in .t files please let me know, and I'll fix it.

@maiste maiste force-pushed the logs/clean-logs-process branch 2 times, most recently from f1bec1d to 0362b79 Compare June 27, 2024 11:35
Copy link
Collaborator

@emillon emillon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The implementation looks good, but I'm concerned with the changes in tests TBH.
The problem isn't really the diff size, but rather that what we're testing doesn't match the reality (real build instructions don't write to files; they output on stdout and stderr).

Since it looks like --display verbose is too verbose, I suggest starting with INSIDE_DUNE so that we can at least land this PR. (I can offer you guidance about how to pretend we're not INSIDE_DUNE to write build-package-logs.t)

Then, in a future PR, we can see how we can make better tests. The pain we're seeing is because we're testing through too many layers, so maybe we could try to define a helper executable that directly executes a package build, or something like that.

@Leonidas-from-XIV
Copy link
Collaborator

real build instructions don't write to files; they output on stdout and stderr

I'd say the opposite, real build instructions write to files and all output to stdout is a side-effect (or execute commands based on filters). In the case of opam the output gets hidden away by default as well, thus if the output was important for builds opam would be breaking them.

@maiste
Copy link
Collaborator Author

maiste commented Jun 27, 2024

I agree with @Leonidas-from-XIV: in the "real build instruction" we write to files (many times it's just a call to dune build). Also, relying on INSIDE_DUNE would not reflect the reality of what happens at the logging level. Maybe, truly rewriting the test (not only changing the output to a file), would be something we want to do once we have a stable structure for pkg and toolchain?

@emillon
Copy link
Collaborator

emillon commented Jun 27, 2024

real build instructions write to files and all output to stdout is a side-effect

Let me clarify what I meant; there are some packages where configure outputs things like paths to stdout.
We also have tests that mimic that with echo %{lib}%, those don't write to files.

Maybe, truly rewriting the test (not only changing the output to a file), would be something we want to do once we have a stable structure for pkg and toolchain?

Yes, that's what I was suggesting; we disagree on the intermediate step. If you use INSIDE_DUNE, you'll have to change the tests only once; by writing to temporary files you'll have to change them twice, with an intermediate state that's a bit messy IMO.

@maiste
Copy link
Collaborator Author

maiste commented Jun 28, 2024

Let me clarify what I meant; there are some packages where configure outputs things like paths to stdout.
We also have tests that mimic that with echo %{lib}%, those don't write to files.

Out of curiosity, is it a test that I updated? 😕

Considering your comment, if we have some packages relying on stdout in the pkg context, suppressing stdout logging would break them. In this scenario, it is not a question of testing, it means that my fix would break some behaviors and make it impossible to have in it dune pkg. Using INSIDE_DUNE would only hide this problem, no? Packages would break at installation time?

Yes, that's what I was suggesting; we disagree on the intermediate step. If you use INSIDE_DUNE, you'll have to change the tests only once; by writing to temporary files you'll have to change them twice, with an intermediate state that's a bit messy IMO.

Technically, the changes are already here: it would be changing them once now ^^ Joke aside, I don't mind removing them: my only concern here is that we would put inside_dune for a behavior that is not only related to dune internally. It would "unsynchronized" the tests from the behavior that happens in "the real world". I agree that the test proposition here is not perfect, and it means we will have to change them at some point. However, this intermediate state allows the tests to break for the right reason: if another PR changes the output but not the internal behavior, it would only break 1 test, not the 30 others.

@emillon
Copy link
Collaborator

emillon commented Jun 28, 2024

Ultimately, you'll be maintaining those tests, so if you're more comfortable with that approach, that's fine by me.

@maiste
Copy link
Collaborator Author

maiste commented Jun 28, 2024

After an offline discussion with @emillon, I agree with his suggestion of adding a flag for printing the output when present, --debug-package-logs.

This way, it provides access to the output when building packages without making dune in the inside_dune mode. The conclusion was to add this so we can merge this PR.

I'll open a new one with the cat version of the tests, so we'll have a proper place to discuss it. As a result, we would be able to merge this PR and use the test PR to sanitize the tests (if we reach the conclusion that this is what we need to do).

@emillon @Leonidas-from-XIV, I let you merge if this is good for you this way.

@maiste maiste force-pushed the logs/clean-logs-process branch 2 times, most recently from 56575c9 to 83e4693 Compare July 1, 2024 08:08
@maiste
Copy link
Collaborator Author

maiste commented Jul 1, 2024

@emillon @Leonidas-from-XIV
I updated the tests and rebase on master. If that's good for you, it should be possible to merge it 👍

Copy link
Collaborator

@emillon emillon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks. You can accept the env var directly in the cmdliner term to simplify the setup and reduce the diff again.
Please add a changelog entry as well.

bin/common.ml Outdated Show resolved Hide resolved
Copy link
Collaborator

@Leonidas-from-XIV Leonidas-from-XIV left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me, can be (squashed &) merged if tests pass.

test/blackbox-tests/test-cases/pkg/helpers.sh Outdated Show resolved Hide resolved
@emillon
Copy link
Collaborator

emillon commented Jul 2, 2024

I'll cleanup the diff and merge. Thanks!

Only logs the standard output when the command fails or the user
explicitly requests it.

Add new flag `--debug-package-logs`, which force dune to display the
stdout logs when dealing with package management.

Signed-off-by: Etienne Marais <[email protected]>
Signed-off-by: Christine Rose <[email protected]>
Signed-off-by: Etienne Millon <[email protected]>
@emillon emillon merged commit 1e8b005 into ocaml:main Jul 2, 2024
27 of 28 checks passed
@maiste maiste deleted the logs/clean-logs-process branch July 2, 2024 13:49
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants