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

Change log level for rules and filesystem intrinsics to trace #10639

Merged
merged 5 commits into from
Aug 18, 2020

Conversation

Eric-Arellano
Copy link
Contributor

@Eric-Arellano Eric-Arellano commented Aug 17, 2020

Currently, -ldebug is not very helpful because it is so noisy. It includes messages like [DEBUG] Completed: Fingerprinting: src/python/pants/util/logging.py for every single file that's fingerprinted, and [DEBUG] Completed: pants.engine.internals.build_files.strip_address_origins hundreds of times becaue we strip source roots for every file.

While this information could indeed be useful, this is why we have -ltrace. -ltrace is when we need an extremely granular view of everything that Pants is doing. -ldebug meanwhile is meant for slightly higher-level messages like [DEBUG] File handle limit is: 20000 or [DEBUG] pants.bin.remote_pants_runner:pid=63445: connecting to pantsd on port 64613 (attempt 1/3).

[ci skip-build-wheels]

# Building wheels and fs_util will be skipped. Delete if not intended.
[ci skip-build-wheels]
Copy link
Contributor Author

@Eric-Arellano Eric-Arellano left a comment

Choose a reason for hiding this comment

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

I added so many of y'all because this is ultimately a bike shed.

@@ -1065,7 +1065,8 @@ impl NodeKey {
fn workunit_level(&self) -> Level {
match self {
NodeKey::Task(ref task) => task.task.display_info.level,
_ => Level::Debug,
NodeKey::DownloadedFile(..) => Level::Debug,
Copy link
Contributor Author

Choose a reason for hiding this comment

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

I set this to Debug because downloading does seem like something more note-worthy than reading from the local FS.

Copy link
Contributor Author

@Eric-Arellano Eric-Arellano Aug 17, 2020

Choose a reason for hiding this comment

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

It's possible that we want other Nodes to be Debug too.

pub enum NodeKey {
DigestFile(DigestFile),
DownloadedFile(DownloadedFile),
MultiPlatformExecuteProcess(Box<MultiPlatformExecuteProcess>),
ReadLink(ReadLink),
Scandir(Scandir),
Select(Box<Select>),
Snapshot(Snapshot),
Task(Box<Task>),
}

Maybe ReadLink?

I don't think MultiPlatformExecuteProcess . Note that MultiPlatformExecuteProcess will have a separate log level for the underlying Process(es) belonging to the MPEP, which defaults to Info and can be overridden in Python in the Process constructor.

Copy link
Contributor

Choose a reason for hiding this comment

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

Agreed re downloads should be debug, filesystem operations (including readlink) should be trace, just due to sheer volume.

@@ -281,7 +281,7 @@ def rule_decorator(func, **kwargs) -> Callable:
if effective_desc is None and is_goal_cls:
effective_desc = f"`{effective_name}` goal"

effective_level = kwargs.get("level", LogLevel.DEBUG)
effective_level = kwargs.get("level", LogLevel.TRACE)
Copy link
Contributor Author

@Eric-Arellano Eric-Arellano Aug 17, 2020

Choose a reason for hiding this comment

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

It's possible that a rule should still default to Debug, and that we override certain noisy rules to Trace. But, still, your typical rule feels trace-y to me.

Imagine if we logged every time you called a normal Python function.

Copy link
Contributor

Choose a reason for hiding this comment

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

Yeah, this is almost the definition of "trace".

@asherf
Copy link
Member

asherf commented Aug 17, 2020

How does this related to the Work units stuff @gshuflin ? I don't follow...

@stuhood
Copy link
Member

stuhood commented Aug 17, 2020

I don't have strong opinions about this. But one thing to think about is: "what else is at trace"? If you use trace, currently you will get output from a lot of rust code: some of it first party, some of it third party. Unless a fair amount of cleanup happens to disable/remove that, anything that you add to the trace level will become unusable. Meaning: without some cleanup to trace, anything you move to trace will become effectively unusable: so unless that cleanup is planned, should probably only move things you don't care to ~ever see.

@Eric-Arellano
Copy link
Contributor Author

Unless a fair amount of cleanup happens to disable/remove that

Is the cleanup removing logs that should not be there because they're too noisy? That sounds like a good thing to do either way.

Also, note that Greg and Tom are working on reviving #10414 in order to filter logs.

These rules would actually be helpful when debugging. They a) have lots of unique logic, and b) are not run hundreds of times in MultiGets.

I think it's still the right decision for rules to default to Trace because that is a more sensible default. We default to the rule not being very interesting, like a rule to go from TestResult -> EnrichedTestResult.

This also automatically updates all @goal_rules to be debug level.

# Rust tests and lints will be skipped. Delete if not intended.
[ci skip-rust]

# Building wheels and fs_util will be skipped. Delete if not intended.
[ci skip-build-wheels]
* Add a description for setting up the Python module maps. Those are pretty hefty rules and they only happen once each.
* Add a description for going from Specs -> AWOs. This also only happens once. It will be helpful in the dynamic UI.
* Stop using Debug for source_files.py and stripped_source_files.py. These end up getting called _a lot_ in one run.

# Rust tests and lints will be skipped. Delete if not intended.
[ci skip-rust]

# Building wheels and fs_util will be skipped. Delete if not intended.
[ci skip-build-wheels]
# Rust tests and lints will be skipped. Delete if not intended.
[ci skip-rust]

# Building wheels and fs_util will be skipped. Delete if not intended.
[ci skip-build-wheels]
@gshuflin
Copy link
Contributor

How does this related to the Work units stuff @gshuflin ? I don't follow...

@asherf @Eric-Arellano workunits have a log level and the streaming workunit handler has its own notion of filtering by log level (see max_workunit_verbosity on the constructor for StreamingWorkunitHandler). Currently this filter defaults to DEBUG, so if we change a bunch of rules to log at TRACE, that will affect what workunits are passed to the streaming handler (and thus to Toolchain's plugin that uses StreamingWorkuntiHandler).

A quick fix for this that won't break anything in any plugin clients of StreamingWorkunitHandler will be to change that default in from DEBUG to TRACE. More broadly, I'm starting to wonder if it's actually a good idea to unify the workunit log level that the streaming handler cares about with what gets logged to the screen. These are fairly different concerns and it's pretty easy for someone to make a change to log levels that works in one domain that breaks things in another domain.

@Eric-Arellano
Copy link
Contributor Author

@gshuflin @asherf do we want every single rule to be used by Toolchain's plugin (or any other workunit consumers)? Some of them are quite uninteresting and noisy, like this rule:

@rule(desc="Run tests")
def enrich_test_result(
test_result: TestResult, test_subsystem: TestSubsystem
) -> EnrichedTestResult:
return EnrichedTestResult(
exit_code=test_result.exit_code,
stdout=test_result.stdout,
stderr=test_result.stderr,
address=test_result.address,
coverage_data=test_result.coverage_data,
xml_results=test_result.xml_results,
output_setting=test_subsystem.output,
)

# Rust tests and lints will be skipped. Delete if not intended.
[ci skip-rust]

# Building wheels and fs_util will be skipped. Delete if not intended.
[ci skip-build-wheels]
@coveralls
Copy link

Coverage Status

Coverage remained the same at 0.0% when pulling 3ae9017 on Eric-Arellano:fingerprint-log into 2ca63be on pantsbuild:master.

@Eric-Arellano Eric-Arellano merged commit cfc48b0 into pantsbuild:master Aug 18, 2020
@Eric-Arellano Eric-Arellano deleted the fingerprint-log branch August 18, 2020 19:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants