Fix filtering of log messages generated in native code. (pantsbuild#1…

…1313)

### 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

@@ -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)

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:

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:

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()
 

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

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]

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<Option<File>>,
   log_file: Mutex<Option<File>>,
@@ -36,6 +38,7 @@ pub struct PantsLogger {
   stderr_handlers: Mutex<HashMap<Uuid, StdioHandler>>,
   show_target: AtomicBool,
   log_level_filters: Mutex<HashMap<String, log::LevelFilter>>,
+  message_regex_filters: Mutex<Vec<Regex>>,
 }
 
 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<String, u64>,
+    message_regex_filters: Vec<Regex>,
   ) {
     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 {

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"

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<String>)
     ),
   )?;
   m.add(
@@ -1778,6 +1779,7 @@ fn init_logging(
   use_color: bool,
   show_target: bool,
   log_levels_by_target: PyDict,
+  message_regex_filters: Vec<String>,
 ) -> PyUnitResult {
   let log_levels_by_target = log_levels_by_target
     .items(py)
@@ -1788,12 +1790,21 @@ fn init_logging(
       (k, v)
     })
     .collect::<HashMap<_, _>>();
+  let message_regex_filters = message_regex_filters
+    .iter()
+    .map(|re| {
+      Regex::new(re).map_err(|e| {
+        PyErr::new::<exc::Exception, _>(py, (format!("Failed to parse warning filter: {}", e),))
+      })
+    })
+    .collect::<Result<Vec<Regex>, _>>()?;
   Logger::init(
     level,
     show_rust_3rdparty_logs,
     use_color,
     show_target,
     log_levels_by_target,
+    message_regex_filters,
   );
   Ok(None)
 }

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)