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

print statements are deduplicated in Bazel 6.0.0rc1 #16721

Closed
fmeum opened this issue Nov 9, 2022 · 10 comments
Closed

print statements are deduplicated in Bazel 6.0.0rc1 #16721

fmeum opened this issue Nov 9, 2022 · 10 comments
Assignees
Labels
team-Core Skyframe, bazel query, BEP, options parsing, bazelrc type: bug

Comments

@fmeum
Copy link
Collaborator

fmeum commented Nov 9, 2022

Description of the bug:

With Bazel 6.0.0rc1, calling print multiple times with the same message in the same location results in only a single line being printed.

What's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

$ touch WORKSPACE
$ echo '[print(x) for x in ["foo", "bar", "foo"]]' > BUILD.bazel
$ USE_BAZEL_VERSION=5.3.2 bazel build //...
DEBUG: .../BUILD.bazel:1:7: foo
DEBUG: .../BUILD.bazel:1:7: bar
DEBUG: .../BUILD.bazel:1:7: foo
$ USE_BAZEL_VERSION=6.0.0rc1 bazel build //...
DEBUG: .../BUILD.bazel:1:7: foo
DEBUG: .../BUILD.bazel:1:7: bar

Which operating system are you running Bazel on?

Linux

What is the output of bazel info release?

6.0.0rc1

If bazel info release returns development version or (@non-git), tell us how you built Bazel.

No response

What's the output of git remote get-url origin; git rev-parse master; git rev-parse HEAD ?

No response

Have you found anything relevant by searching the web?

No response

Any other information, logs, or outputs that you want to share?

No response

@fmeum
Copy link
Collaborator Author

fmeum commented Nov 9, 2022

@bazel-io flag

@bazel-io bazel-io added the potential release blocker Flagged by community members using "@bazel-io flag". Should be added to a release blocker milestone label Nov 9, 2022
@fmeum
Copy link
Collaborator Author

fmeum commented Nov 9, 2022

My local bisect points to 3f5edd8.

@justinhorvitz Is it possible that 3f5edd8 resulted in events being deduped if they compare equal?

@justinhorvitz
Copy link
Contributor

Quite possibly. I can see how that change might affect print statements. I will look into this.

@justinhorvitz justinhorvitz self-assigned this Nov 9, 2022
@justinhorvitz
Copy link
Contributor

--notrack_incremental_state still prints twice because it doesn't store the events and bypasses the deduplication filter. Also, print statements within a rule's implementation function will still print multiple times for different rules, since the event gets "tagged" with the rule label.

I'll try to restore the previous behavior.

@justinhorvitz
Copy link
Contributor

There's another curious case which as far as I can tell never worked. Two different packages call the same macro in a bzl file, and that calls print. That was always deduplicated because it was from different sky functions (assuming no other prints or other events involved).

@fmeum
Copy link
Collaborator Author

fmeum commented Nov 11, 2022

@justinhorvitz Thanks for the quick fix! Could you cherry-pick it to the release-6.0.0 branch?

@justinhorvitz
Copy link
Contributor

I wouldn't be the person to talk to to request a bazel cherrypick, but regardless we need to resolve #16746 first. Maybe @meteorcloudy can help with the cherrypick request?

@meteorcloudy
Copy link
Member

@bazel-io fork 6.0.0

@bazel-io bazel-io removed the potential release blocker Flagged by community members using "@bazel-io flag". Should be added to a release blocker milestone label Nov 14, 2022
@meteorcloudy
Copy link
Member

Yes, I think we should cherry pick this one

@ShreeM01
Copy link
Contributor

Yes, I think we should cherry pick this one

Hello @meteorcloudy! Here we are #16762. Thanks!

ShreeM01 added a commit that referenced this issue Nov 14, 2022
The primary source of `DEBUG` events is the starlark `print()` function. The motivation in making this change is to emit `print()` statements more intelligibly, including:

* Not deduplicating multiple identical prints from the same line of code.
* Not replaying prints when the corresponding skyframe node is cached. For example, we currently replay prints in a `BUILD` file even when the package is up to date and the starlark code is not executed.

A secondary benefit is that we don't spend memory retaining `DEBUG` events in skyframe.

This change makes `DEBUG` events match the semantics of `INFO` and `PROGRESS` events. See the documentation on `Reportable#storeForReplay`. There is some chance that this causes additional spam or breaks something relying on cached print statements in incremental build output, but per [style guide](https://bazel.build/rules/bzl-style#print-for-debugging), `print()` should not be used for production code anyway.

There are a couple other minor sources of `DEBUG` events besides `print()`, and those semantics will be changed as well (for the better, in my opinion).

Fixes #16721.

RELNOTES: Starlark `print()` statements are now emitted iff the line of code is executed. They are no longer replayed on subsequent invocations unless the Starlark code is re-executed. Additionally, multiple identical `print()` statements (same string from the same line of code, e.g. from a loop) are all emitted and no longer deduplicated.
PiperOrigin-RevId: 487645012
Change-Id: I8b13df67febc9f330c864930688bca31c3711276

Co-authored-by: Googler <jhorvitz@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
team-Core Skyframe, bazel query, BEP, options parsing, bazelrc type: bug
Projects
None yet
Development

No branches or pull requests

6 participants
@meteorcloudy @fmeum @bazel-io @justinhorvitz @ShreeM01 and others