From 9e9d7c34d134026c59e241a8c2f6b86f7d60bd59 Mon Sep 17 00:00:00 2001 From: Stu Hood Date: Tue, 15 Dec 2020 18:00:07 -0800 Subject: [PATCH] Fix filtering of log messages generated in native code. (#11313) ### Problem Log messages generated in native code (including those generated by `--files-not-found-behavior=warn`) cannot be filtered using the Python warnings module, meaning that the `--ignore-pants-warnings` option does not currently work for them. ### Solution Move to a native implementation of warnings filtering, which allows for filtering out log messages generated by Rust as well as Python. [ci skip-build-wheels] --- src/python/pants/bin/pants_runner.py | 3 +-- src/python/pants/engine/internals/native.py | 8 ++++++- src/python/pants/init/logging.py | 25 +++++++++++--------- src/python/pants/pantsd/pants_daemon.py | 7 +++--- src/python/pants/pantsd/pants_daemon_core.py | 2 -- src/rust/engine/Cargo.lock | 1 + src/rust/engine/logging/Cargo.toml | 1 + src/rust/engine/logging/src/logger.rs | 16 +++++++++++++ src/rust/engine/process_execution/Cargo.toml | 2 +- src/rust/engine/src/externs/interface.rs | 13 +++++++++- tests/python/pants_test/init/test_logging.py | 2 ++ 11 files changed, 58 insertions(+), 22 deletions(-) diff --git a/src/python/pants/bin/pants_runner.py b/src/python/pants/bin/pants_runner.py index 0cfc6b749b3..93c9d32a26d 100644 --- a/src/python/pants/bin/pants_runner.py +++ b/src/python/pants/bin/pants_runner.py @@ -10,7 +10,7 @@ from pants.base.exception_sink import ExceptionSink from pants.base.exiter import ExitCode from pants.bin.remote_pants_runner import RemotePantsRunner -from pants.init.logging import setup_logging, setup_warning_filtering +from pants.init.logging import setup_logging from pants.init.util import init_workdir from pants.option.option_value_container import OptionValueContainer from pants.option.options_bootstrapper import OptionsBootstrapper @@ -67,7 +67,6 @@ def run(self, start_time: float) -> ExitCode: bootstrap_options = options_bootstrapper.bootstrap_options global_bootstrap_options = bootstrap_options.for_global_scope() - setup_warning_filtering(global_bootstrap_options.ignore_pants_warnings or []) # We enable logging here, and everything before it will be routed through regular # Python logging. setup_logging(global_bootstrap_options, stderr_logging=True) diff --git a/src/python/pants/engine/internals/native.py b/src/python/pants/engine/internals/native.py index d273d9c137d..789d8c85869 100644 --- a/src/python/pants/engine/internals/native.py +++ b/src/python/pants/engine/internals/native.py @@ -133,10 +133,16 @@ def init_rust_logging( use_color: bool, show_target: bool, log_levels_by_target: Mapping[str, LogLevel], + message_regex_filters: Iterable[str], ): log_levels_as_ints = {k: v.level for k, v in log_levels_by_target.items()} return self.lib.init_logging( - level, log_show_rust_3rdparty, use_color, show_target, log_levels_as_ints + level, + log_show_rust_3rdparty, + use_color, + show_target, + log_levels_as_ints, + tuple(message_regex_filters), ) def set_per_run_log_path(self, path: Optional[str]) -> None: diff --git a/src/python/pants/init/logging.py b/src/python/pants/init/logging.py index efb3b887c3e..34fbe2887da 100644 --- a/src/python/pants/init/logging.py +++ b/src/python/pants/init/logging.py @@ -4,7 +4,6 @@ import http.client import logging import os -import warnings from logging import Formatter, Handler, LogRecord, StreamHandler from typing import Dict, Iterable, Optional, Tuple @@ -27,20 +26,18 @@ def init_rust_logger( use_color: bool, show_target: bool, log_levels_by_target: Dict[str, LogLevel] = {}, + message_regex_filters: Iterable[str] = (), ) -> None: Native().init_rust_logging( - log_level.level, log_show_rust_3rdparty, use_color, show_target, log_levels_by_target + log_level.level, + log_show_rust_3rdparty, + use_color, + show_target, + log_levels_by_target, + message_regex_filters, ) -def setup_warning_filtering(warnings_filter_regexes: Iterable[str]) -> None: - """Sets up regex-based ignores for messages using the Python warnings system.""" - - warnings.resetwarnings() - for message_regexp in warnings_filter_regexes or (): - warnings.filterwarnings(action="ignore", message=message_regexp) - - class NativeHandler(StreamHandler): """This class is installed as a Python logging module handler (using the logging.addHandler method) and proxies logs to the Rust logging infrastructure.""" @@ -130,9 +127,15 @@ def setup_logging(global_bootstrap_options: OptionValueContainer, stderr_logging use_color = global_bootstrap_options.colors show_target = global_bootstrap_options.show_log_target log_levels_by_target = get_log_levels_by_target(global_bootstrap_options) + message_regex_filters = global_bootstrap_options.ignore_pants_warnings init_rust_logger( - global_level, log_show_rust_3rdparty, use_color, show_target, log_levels_by_target + global_level, + log_show_rust_3rdparty, + use_color, + show_target, + log_levels_by_target, + message_regex_filters, ) if stderr_logging: diff --git a/src/python/pants/pantsd/pants_daemon.py b/src/python/pants/pantsd/pants_daemon.py index 6f54f64ba0f..79bd7849a9e 100644 --- a/src/python/pants/pantsd/pants_daemon.py +++ b/src/python/pants/pantsd/pants_daemon.py @@ -18,7 +18,7 @@ from pants.bin.daemon_pants_runner import DaemonPantsRunner from pants.engine.internals.native import Native from pants.init.engine_initializer import GraphScheduler -from pants.init.logging import setup_logging, setup_logging_to_file, setup_warning_filtering +from pants.init.logging import setup_logging, setup_logging_to_file from pants.init.options_initializer import OptionsInitializer from pants.init.util import init_workdir from pants.option.option_value_container import OptionValueContainer @@ -48,13 +48,12 @@ class RuntimeFailure(Exception): @classmethod def create(cls, options_bootstrapper: OptionsBootstrapper) -> PantsDaemon: - + # Any warnings that would be triggered here are re-triggered later per-run of Pants, so we + # silence them. with warnings.catch_warnings(record=True): bootstrap_options = options_bootstrapper.bootstrap_options bootstrap_options_values = bootstrap_options.for_global_scope() - setup_warning_filtering(bootstrap_options_values.ignore_pants_warnings or []) - native = Native() native.override_thread_logging_destination_to_just_pantsd() diff --git a/src/python/pants/pantsd/pants_daemon_core.py b/src/python/pants/pantsd/pants_daemon_core.py index 59690da84ed..451b31f492f 100644 --- a/src/python/pants/pantsd/pants_daemon_core.py +++ b/src/python/pants/pantsd/pants_daemon_core.py @@ -8,7 +8,6 @@ from typing_extensions import Protocol from pants.init.engine_initializer import EngineInitializer, GraphScheduler -from pants.init.logging import setup_warning_filtering from pants.init.options_initializer import BuildConfigInitializer from pants.option.option_value_container import OptionValueContainer from pants.option.options_bootstrapper import OptionsBootstrapper @@ -77,7 +76,6 @@ def _init_scheduler( build_config = BuildConfigInitializer.get(options_bootstrapper) self._scheduler = EngineInitializer.setup_graph(options_bootstrapper, build_config) bootstrap_options_values = options_bootstrapper.bootstrap_options.for_global_scope() - setup_warning_filtering(bootstrap_options_values.ignore_pants_warnings or []) self._services = self._services_constructor(bootstrap_options_values, self._scheduler) self._fingerprint = options_fingerprint diff --git a/src/rust/engine/Cargo.lock b/src/rust/engine/Cargo.lock index d5d3051f757..0b7639cbebe 100644 --- a/src/rust/engine/Cargo.lock +++ b/src/rust/engine/Cargo.lock @@ -1549,6 +1549,7 @@ dependencies = [ "log 0.4.8", "num_enum", "parking_lot", + "regex", "tokio", "uuid 0.7.4", ] diff --git a/src/rust/engine/logging/Cargo.toml b/src/rust/engine/logging/Cargo.toml index 5960872bbf0..c750d7dd688 100644 --- a/src/rust/engine/logging/Cargo.toml +++ b/src/rust/engine/logging/Cargo.toml @@ -13,6 +13,7 @@ log = "0.4" num_enum = "0.4" parking_lot = "0.11" tokio = { version = "0.2.23", features = ["rt-util"] } +regex = "1" uuid = { version = "0.7", features = ["v4"] } [build-dependencies] diff --git a/src/rust/engine/logging/src/logger.rs b/src/rust/engine/logging/src/logger.rs index 1d2873509e7..10349432371 100644 --- a/src/rust/engine/logging/src/logger.rs +++ b/src/rust/engine/logging/src/logger.rs @@ -16,6 +16,7 @@ use std::sync::atomic::{AtomicBool, Ordering}; use lazy_static::lazy_static; use log::{debug, log, set_logger, set_max_level, LevelFilter, Log, Metadata, Record}; use parking_lot::Mutex; +use regex::Regex; use tokio::task_local; use uuid::Uuid; @@ -27,6 +28,7 @@ lazy_static! { pub static ref PANTS_LOGGER: PantsLogger = PantsLogger::new(); } +// TODO: The non-atomic portions of this struct should likely be composed into a single RwLock. pub struct PantsLogger { per_run_logs: Mutex>, log_file: Mutex>, @@ -36,6 +38,7 @@ pub struct PantsLogger { stderr_handlers: Mutex>, show_target: AtomicBool, log_level_filters: Mutex>, + message_regex_filters: Mutex>, } impl PantsLogger { @@ -49,6 +52,7 @@ impl PantsLogger { stderr_handlers: Mutex::new(HashMap::new()), show_target: AtomicBool::new(false), log_level_filters: Mutex::new(HashMap::new()), + message_regex_filters: Mutex::new(Vec::new()), } } @@ -58,6 +62,7 @@ impl PantsLogger { use_color: bool, show_target: bool, log_levels_by_target: HashMap, + message_regex_filters: Vec, ) { let log_levels_by_target = log_levels_by_target .iter() @@ -84,6 +89,7 @@ impl PantsLogger { .show_rust_3rdparty_logs .store(show_rust_3rdparty_logs, Ordering::SeqCst); *PANTS_LOGGER.log_level_filters.lock() = log_levels_by_target; + *PANTS_LOGGER.message_regex_filters.lock() = message_regex_filters; PANTS_LOGGER .show_target .store(show_target, Ordering::SeqCst); @@ -235,6 +241,16 @@ impl Log for PantsLogger { format!("{} {} {}", time_str, level_marker, record.args()) }; + { + let message_regex_filters = self.message_regex_filters.lock(); + if message_regex_filters + .iter() + .any(|re| re.is_match(&log_string)) + { + return; + } + } + { let mut maybe_per_run_file = self.per_run_logs.lock(); if let Some(ref mut file) = *maybe_per_run_file { diff --git a/src/rust/engine/process_execution/Cargo.toml b/src/rust/engine/process_execution/Cargo.toml index 36310bd790e..598d1baf490 100644 --- a/src/rust/engine/process_execution/Cargo.toml +++ b/src/rust/engine/process_execution/Cargo.toml @@ -35,7 +35,7 @@ tokio-util = { version = "0.2", features = ["codec"] } uname = "0.1.1" uuid = { version = "0.7", features = ["v4"] } workunit_store = { path = "../workunit_store" } -regex = "1.3.1" +regex = "1" lazy_static = "1" parking_lot = "0.11" itertools = "0.8.0" diff --git a/src/rust/engine/src/externs/interface.rs b/src/rust/engine/src/externs/interface.rs index 7172447d950..699aba37012 100644 --- a/src/rust/engine/src/externs/interface.rs +++ b/src/rust/engine/src/externs/interface.rs @@ -66,6 +66,7 @@ use hashing::Digest; use log::{self, debug, error, warn, Log}; use logging::logger::PANTS_LOGGER; use logging::{Destination, Logger, PythonLogLevel}; +use regex::Regex; use rule_graph::{self, RuleGraph}; use std::collections::hash_map::HashMap; use task_executor::Executor; @@ -103,7 +104,7 @@ py_module_initializer!(native_engine, |py, m| { "init_logging", py_fn!( py, - init_logging(a: u64, b: bool, c: bool, d: bool, e: PyDict) + init_logging(a: u64, b: bool, c: bool, d: bool, e: PyDict, f: Vec) ), )?; m.add( @@ -1778,6 +1779,7 @@ fn init_logging( use_color: bool, show_target: bool, log_levels_by_target: PyDict, + message_regex_filters: Vec, ) -> PyUnitResult { let log_levels_by_target = log_levels_by_target .items(py) @@ -1788,12 +1790,21 @@ fn init_logging( (k, v) }) .collect::>(); + let message_regex_filters = message_regex_filters + .iter() + .map(|re| { + Regex::new(re).map_err(|e| { + PyErr::new::(py, (format!("Failed to parse warning filter: {}", e),)) + }) + }) + .collect::, _>>()?; Logger::init( level, show_rust_3rdparty_logs, use_color, show_target, log_levels_by_target, + message_regex_filters, ); Ok(None) } diff --git a/tests/python/pants_test/init/test_logging.py b/tests/python/pants_test/init/test_logging.py index da09a71209c..f60f759b2bd 100644 --- a/tests/python/pants_test/init/test_logging.py +++ b/tests/python/pants_test/init/test_logging.py @@ -18,6 +18,7 @@ def test_file_logging() -> None: use_color=False, show_target=False, log_levels_by_target={}, + message_regex_filters=(), ) logger = logging.getLogger("my_file_logger") with temporary_dir() as tmpdir: @@ -48,6 +49,7 @@ def test_log_filtering_by_rule() -> None: log_levels_by_target={ "debug_target": LogLevel.DEBUG, }, + message_regex_filters=(), ) with temporary_dir() as tmpdir: setup_logging_to_file(LogLevel.INFO, log_dir=tmpdir)