Filter log levels by target #10729

gshuflin · 2020-09-03T23:07:27Z

Problem

Pants's logging, particularly on the DEBUG and TRACE levels, is too verbose to make effective use of. We would like to be able to selectively enable more verbose logging for specific areas of the pants codebase where we think a problem we're trying to debug might lie, while leaving others at the default logging level.

Solution

The Rust and Python logging frameworks that Pants uses already have the concept of a target, that is, a name associated with a log object that comes from the area of the codebase where that log is emitted. For Python logs, that target name is a fully-qualified Python module (e.g. pants.pantsd.service.pants_service) and for Rust logs it is the name of the Rust module (e.g. workunit_store).

This commit adds a new global option --log-levels-by-target that expects a dictionary mapping strings representing these target names to the string representation of a Pants log level. By this mechanism, a user can specify that logs originating in a given part of the pants codebase will be subject to less filtering than other logs. Log targets not explicitly specified in this option are filtered according to the global log level specified with --level.

This commit also adds another new global option --show-log-target that simply adds the target name to log messages without doing any filtering, to make it easier for users casually inspecting logs to see what log targets might be relevant for further debugging.

tdyas

lgtm

tdyas · 2020-09-03T23:44:20Z

src/rust/engine/logging/src/logger.rs

-        set_max_level(level);
+        // TODO this should be whatever the most verbose log level specified in log_domain_levels -
+        // but I'm not sure if it's actually much of a gain over just setting this to Trace.
+        set_max_level(LevelFilter::Trace);


Does this mean we would be formatting the strings for log messages only to discard them?

@tdyas with this change we would execute format strings in Rust log! macros (and debug!, etc.), but we wouldn't generate the final format string in PantsLogger::log since that only gets executed if PantsLogger::enabled is true. If the performance hit from doing too much trace-level string formatting is too bad, we could probably hook into whatever system the log macros are using to know whether they need to print, and make that aware of this option too.

Eric-Arellano

Neat!

Eric-Arellano · 2020-09-03T23:42:12Z

src/rust/engine/logging/src/logger.rs

@@ -112,13 +146,26 @@ impl PantsLogger {

 impl Log for PantsLogger {
  fn enabled(&self, metadata: &Metadata) -> bool {
-    metadata.level() <= max_level()
+    let global_level: LevelFilter = { *self.global_level.lock().borrow() };


Is calling *foo.borrow() the same thing as *&foo, which I would expect to be the same thing as foo but I think isn't?

borrow is a method defined on RefCell (https://doc.rust-lang.org/std/cell/struct.RefCell.html#method.borrow). However, I don't think I actually need Mutex<RefCell<T>>, just a Mutex should be fine here, so I'm removing this call.

Eric-Arellano · 2020-09-03T23:44:13Z

src/rust/engine/logging/src/logger.rs

+    let global_level: LevelFilter = { *self.global_level.lock().borrow() };
+    let enabled_globally = metadata.level() <= global_level;
+    let log_level_filters_lock = self.log_level_filters.lock();
+    let log_level_filters = log_level_filters_lock.borrow();


Same thing as &log_level_filters_lock? (I'm trying to understand .borrow())

Eric-Arellano · 2020-09-03T23:48:05Z

src/python/pants/option/global_options.py

+            type=bool,
+            default=False,
+            advanced=True,
+            help="Display the target where a log message originates in that log message's output.",


Maybe add: "This can be helpful when paired with the option --log-levels-by-target"

Eric-Arellano · 2020-09-03T23:50:17Z

src/python/pants/option/global_options.py

+            help="Set a more specific logging level for one or more logging targets. "
+            "The logging levels are one of: "
+            '"error", "warn", "info", "debug", "trace".',


It'd be good to give an example. Maybe something like:

Set a more specific logging level for one or more logging targets. You can find the target names by enabling --log-levels-by-target. The logging levels are one of "error", "warn", "info", "debug", "trace". All unspecified targets use the global level set by -l/--level. For example, you can set {"workunit_store": "info", "pants.engine.rules": "warn"}

Eric-Arellano · 2020-09-03T23:51:16Z

src/python/pants/init/logging.py

+            raise ValueError("keys for log_domain_levels must be strings")
+        if not isinstance(value, str):
+            raise ValueError("values for log_domain_levels must be strings")


Would be good to include the bad value.

"Keys for log_domain_levels must be strings, but was given the key 1232 with type 'int'."

Eric-Arellano · 2020-09-03T23:52:36Z

src/python/pants/engine/internals/native.py

+        log_show_rust_3rdparty: bool,
+        use_color: bool,
+        show_target: bool,
+        log_levels_by_target: Dict[str, LogLevel],


Nit: the type hint for log_levels_by_target everywhere can be Mapping, given that you convert it into a dict on the next line.

Not a big deal, but can be useful given how frequently we use FrozenDict.

Eric-Arellano · 2020-09-03T23:53:35Z

src/python/pants/init/logging.py

-        self.native.write_log(
-            msg=self.format(record), level=record.levelno, target=f"{record.name}:pid={os.getpid()}"
-        )
+        self.native.write_log(msg=self.format(record), level=record.levelno, target=record.name)


+1 to getting rid of the PID.

Eric-Arellano · 2020-09-03T23:54:27Z

tests/python/pants_test/integration/log_output_integration_test.py

+    sources = {
+        "src/python/project/__init__.py": "",
+        "src/python/project/lib.py": dedent(
+            """\
+            def add(x: int, y: int) -> int:
+                return x + y
+            """
+        ),
+        "src/python/project/BUILD": "python_library()",
+    }


Rather than copying and pasting, can you please either use a @pytest.fixture or make this value be a module-level constant?

Actually, I don't think there's any need for this source file, if all you're running is list. It's fine to have no tmpdir afaict.

coveralls · 2020-09-04T00:10:18Z

Coverage remained the same at 0.0% when pulling 69b56db on gshuflin:filter_logs into 91921db on pantsbuild:master.

Also remove PID in log target, explicitly log pantsd PID one time at startup [ci skip-build-wheels]

[ci skip-build-wheels]

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

stuhood · 2020-09-14T22:20:07Z

(Large?) nit: "target" already has a pretty specific meaning in pants: https://www.pantsbuild.org/docs/target-api

gshuflin requested review from stuhood, jsirois, tdyas and Eric-Arellano September 3, 2020 23:07

tdyas approved these changes Sep 3, 2020

View reviewed changes

tdyas reviewed Sep 3, 2020

View reviewed changes

Eric-Arellano reviewed Sep 3, 2020

View reviewed changes

gshuflin force-pushed the filter_logs branch from ce5df2a to 2e8cbb1 Compare September 4, 2020 02:12

gshuflin marked this pull request as ready for review September 4, 2020 02:12

gshuflin force-pushed the filter_logs branch from 36fe18d to d7d48f0 Compare September 4, 2020 05:53

gshuflin added 7 commits September 4, 2020 10:45

Add --show-log-target option

273cd6f

Also remove PID in log target, explicitly log pantsd PID one time at startup [ci skip-build-wheels]

Add --log-levels-by-target option

97c4b2e

[ci skip-build-wheels]

Add filter logic

c569e53

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

Add tests

64fa6a4

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

test improvements

565506c

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

PR fixes

deb2b3a

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

Add type length limit to make build process happy

69b56db

gshuflin force-pushed the filter_logs branch from d7d48f0 to 69b56db Compare September 4, 2020 17:45

gshuflin merged commit a403445 into pantsbuild:master Sep 4, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Filter log levels by target #10729

Filter log levels by target #10729

gshuflin commented Sep 3, 2020 •

edited

tdyas left a comment

tdyas Sep 3, 2020

gshuflin Sep 3, 2020

Eric-Arellano left a comment

Eric-Arellano Sep 3, 2020

gshuflin Sep 4, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

Eric-Arellano Sep 3, 2020

coveralls commented Sep 4, 2020 •

edited

stuhood commented Sep 14, 2020

Filter log levels by target #10729

Filter log levels by target #10729

Conversation

gshuflin commented Sep 3, 2020 • edited

Problem

Solution

tdyas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Eric-Arellano left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

coveralls commented Sep 4, 2020 • edited

stuhood commented Sep 14, 2020

gshuflin commented Sep 3, 2020 •

edited

coveralls commented Sep 4, 2020 •

edited