Merge 69b56db into 91921db

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

@@ -3,7 +3,7 @@
 
 import logging
 import os
-from typing import Dict, Iterable, List, Tuple, Union, cast
+from typing import Dict, Iterable, List, Mapping, Tuple, Union, cast
 
 from typing_extensions import Protocol
 
@@ -26,6 +26,7 @@
 )
 from pants.engine.rules import Get
 from pants.engine.unions import union
+from pants.util.logging import LogLevel
 from pants.util.memo import memoized_property
 from pants.util.meta import SingletonMetaclass
 
@@ -130,8 +131,18 @@ def lib(self):
     def decompress_tarball(self, tarfile_path, dest_dir):
         return self.lib.decompress_tarball(tarfile_path, dest_dir)
 
-    def init_rust_logging(self, level, log_show_rust_3rdparty: bool, use_color: bool):
-        return self.lib.init_logging(level, log_show_rust_3rdparty, use_color)
+    def init_rust_logging(
+        self,
+        level: int,
+        log_show_rust_3rdparty: bool,
+        use_color: bool,
+        show_target: bool,
+        log_levels_by_target: Mapping[str, LogLevel],
+    ):
+        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
+        )
 
     def default_cache_path(self) -> str:
         return cast(str, self.lib.default_cache_path())

src/python/pants/init/logging.py

@@ -6,11 +6,12 @@
 import os
 import warnings
 from logging import Formatter, Handler, LogRecord, StreamHandler
-from typing import List, Optional, Tuple
+from typing import Dict, List, Optional, Tuple
 
 import pants.util.logging as pants_logging
 from pants.base.exception_sink import ExceptionSink
 from pants.engine.internals.native import Native
+from pants.option.option_value_container import OptionValueContainer
 from pants.util.dirutil import safe_mkdir
 from pants.util.logging import LogLevel
 
@@ -21,8 +22,16 @@
 logging.addLevelName(pants_logging.TRACE, "TRACE")
 
 
-def init_rust_logger(log_level: LogLevel, log_show_rust_3rdparty: bool, use_color: bool) -> None:
-    Native().init_rust_logging(log_level.level, log_show_rust_3rdparty, use_color)
+def init_rust_logger(
+    log_level: LogLevel,
+    log_show_rust_3rdparty: bool,
+    use_color: bool,
+    show_target: bool,
+    log_levels_by_target: Dict[str, LogLevel] = {},
+) -> None:
+    Native().init_rust_logging(
+        log_level.level, log_show_rust_3rdparty, use_color, show_target, log_levels_by_target
+    )
 
 
 class NativeHandler(StreamHandler):
@@ -33,14 +42,12 @@ def __init__(self, log_level: LogLevel, native_filename: Optional[str] = None) -
         super().__init__(None)
         self.native = Native()
         self.native_filename = native_filename
-        self.setLevel(log_level.level)
+        self.setLevel(pants_logging.TRACE)
         if not self.native_filename:
             self.native.setup_stderr_logger()
 
     def emit(self, record: LogRecord) -> None:
-        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)
 
     def flush(self) -> None:
         self.native.flush_log()
@@ -114,13 +121,34 @@ def setup_logging(global_bootstrap_options):
 
     log_show_rust_3rdparty = global_bootstrap_options.log_show_rust_3rdparty
     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)
 
-    init_rust_logger(global_level, log_show_rust_3rdparty, use_color)
+    init_rust_logger(
+        global_level, log_show_rust_3rdparty, use_color, show_target, log_levels_by_target
+    )
     setup_logging_to_stderr(global_level, warnings_filter_regexes=ignores)
     if log_dir:
         setup_logging_to_file(global_level, log_dir=log_dir, warnings_filter_regexes=ignores)
 
 
+def get_log_levels_by_target(global_bootstrap_options: OptionValueContainer) -> Dict[str, LogLevel]:
+    raw_levels = global_bootstrap_options.log_levels_by_target
+    levels: Dict[str, LogLevel] = {}
+    for key, value in raw_levels.items():
+        if not isinstance(key, str):
+            raise ValueError(
+                "Keys for log_domain_levels must be strings, but was given the key: {key} with type {type(key)}."
+            )
+        if not isinstance(value, str):
+            raise ValueError(
+                "Values for log_domain_levels must be strings, but was given the value: {value} with type {type(value)}."
+            )
+        log_level = LogLevel[value.upper()]
+        levels[key] = log_level
+    return levels
+
+
 def setup_logging_to_stderr(
     level: LogLevel, *, warnings_filter_regexes: Optional[List[str]] = None
 ) -> None:

src/python/pants/option/global_options.py

@@ -168,7 +168,29 @@ def register_bootstrap_options(cls, register):
             "--level",
             type=LogLevel,
             default=LogLevel.INFO,
-            help="Set the logging level.",
+            help="Set the logging level. The logging levels are one of: "
+            '"error", "warn", "info", "debug", "trace".',
+        )
+        register(
+            "--show-log-target",
+            type=bool,
+            default=False,
+            advanced=True,
+            help="Display the target where a log message originates in that log message's output. "
+            "This can be helpful when paired with --log-levels-by-target.",
+        )
+
+        register(
+            "--log-levels-by-target",
+            type=dict,
+            default={},
+            advanced=True,
+            help="Set a more specific logging level for one or more logging targets. The names of "
+            "logging targets are specified in log strings when the --show-log-target option is set. "
+            "The logging levels are one of: "
+            '"error", "warn", "info", "debug", "trace". '
+            "All logging targets not specified here use the global log level set with --level. For example, "
+            'you can set `--log-levels-by-target=\'{"workunit_store": "info", "pants.engine.rules": "warn"}\'` ',
         )
 
         register(

src/python/pants/pantsd/pants_daemon.py

@@ -214,8 +214,15 @@ def _pantsd_logging(self) -> Iterator[IO[str]]:
         # for further forks.
         with stdio_as(stdin_fd=-1, stdout_fd=-1, stderr_fd=-1):
             # Reinitialize logging for the daemon context.
-            use_color = self._bootstrap_options.for_global_scope().colors
-            init_rust_logger(self._log_level, self._log_show_rust_3rdparty, use_color=use_color)
+            global_options = self._bootstrap_options.for_global_scope()
+            use_color = global_options.colors
+            show_target = global_options.show_log_target
+            init_rust_logger(
+                self._log_level,
+                self._log_show_rust_3rdparty,
+                use_color=use_color,
+                show_target=show_target,
+            )
 
             level = self._log_level
             ignores = self._bootstrap_options.for_global_scope().ignore_pants_warnings
@@ -249,6 +256,7 @@ def _initialize_pid(self):
 
         # Write the pidfile. The SchedulerService will monitor it after a grace period.
         pid = os.getpid()
+        self._logger.debug(f"pantsd running with PID: {pid}")
         self.write_pid(pid=pid)
         self.write_metadata_by_name(
             "pantsd", self.FINGERPRINT_KEY, ensure_text(self.options_fingerprint)

src/rust/engine/fs/fs_util/src/main.rs

@@ -26,6 +26,7 @@
 #![allow(clippy::new_without_default, clippy::new_ret_no_self)]
 // Arc<Mutex> can be more clear than needing to grok Orderings:
 #![allow(clippy::mutex_atomic)]
+#![type_length_limit = "1880979"]
 
 use std::convert::TryInto;
 use std::io::{self, Write};

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

@@ -14,7 +14,7 @@ use std::path::PathBuf;
 use std::sync::atomic::{AtomicBool, Ordering};
 
 use lazy_static::lazy_static;
-use log::{debug, log, max_level, set_logger, set_max_level, LevelFilter, Log, Metadata, Record};
+use log::{debug, log, set_logger, set_max_level, LevelFilter, Log, Metadata, Record};
 use parking_lot::Mutex;
 use tokio::task_local;
 use uuid::Uuid;
@@ -29,31 +29,62 @@ lazy_static! {
 
 pub struct PantsLogger {
   log_file: Mutex<Option<File>>,
+  global_level: Mutex<RefCell<LevelFilter>>,
   use_color: AtomicBool,
   show_rust_3rdparty_logs: AtomicBool,
   stderr_handlers: Mutex<HashMap<Uuid, StdioHandler>>,
+  show_target: AtomicBool,
+  log_level_filters: Mutex<HashMap<String, log::LevelFilter>>,
 }
 
 impl PantsLogger {
   pub fn new() -> PantsLogger {
     PantsLogger {
       log_file: Mutex::new(None),
+      global_level: Mutex::new(RefCell::new(LevelFilter::Off)),
       show_rust_3rdparty_logs: AtomicBool::new(true),
       use_color: AtomicBool::new(false),
       stderr_handlers: Mutex::new(HashMap::new()),
+      show_target: AtomicBool::new(false),
+      log_level_filters: Mutex::new(HashMap::new()),
     }
   }
 
-  pub fn init(max_level: u64, show_rust_3rdparty_logs: bool, use_color: bool) {
+  pub fn init(
+    max_level: u64,
+    show_rust_3rdparty_logs: bool,
+    use_color: bool,
+    show_target: bool,
+    log_levels_by_target: HashMap<String, u64>,
+  ) {
+    let log_levels_by_target = log_levels_by_target
+      .iter()
+      .map(|(k, v)| {
+        let python_level: PythonLogLevel = (*v).try_into().unwrap_or_else(|e| {
+          panic!("Unrecognized log level from python: {}: {}", v, e);
+        });
+        let level: log::LevelFilter = python_level.into();
+        (k.clone(), level)
+      })
+      .collect::<HashMap<_, _>>();
+
     let max_python_level: Result<PythonLogLevel, _> = max_level.try_into();
     match max_python_level {
       Ok(python_level) => {
         let level: LevelFilter = python_level.into();
-        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);
+        PANTS_LOGGER.global_level.lock().replace(level);
+
         PANTS_LOGGER.use_color.store(use_color, Ordering::SeqCst);
         PANTS_LOGGER
           .show_rust_3rdparty_logs
           .store(show_rust_3rdparty_logs, Ordering::SeqCst);
+        *PANTS_LOGGER.log_level_filters.lock() = log_levels_by_target;
+        PANTS_LOGGER
+          .show_target
+          .store(show_target, Ordering::SeqCst);
         if set_logger(&*PANTS_LOGGER).is_err() {
           debug!("Logging already initialized.");
         }
@@ -112,13 +143,25 @@ 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() };
+    let enabled_globally = metadata.level() <= global_level;
+    let log_level_filters = self.log_level_filters.lock();
+    let enabled_for_target = log_level_filters
+      .get(metadata.target())
+      .map(|lf| metadata.level() <= *lf)
+      .unwrap_or(false);
+
+    enabled_globally || enabled_for_target
   }
 
   fn log(&self, record: &Record) {
     use chrono::Timelike;
     use log::Level;
 
+    if !self.enabled(record.metadata()) {
+      return;
+    }
+
     let mut should_log = self.show_rust_3rdparty_logs.load(Ordering::SeqCst);
     if !should_log {
       if let Some(ref module_path) = record.module_path() {
@@ -144,6 +187,7 @@ impl Log for PantsLogger {
       cur_date.time().nanosecond() / 10_000_000 // Two decimal places of precision.
     );
 
+    let show_target = self.show_target.load(Ordering::SeqCst);
     let level = record.level();
     let destination_is_file = match destination {
       Destination::Pantsd => true,
@@ -160,7 +204,17 @@ impl Log for PantsLogger {
       Level::Trace => format!("[{}]", level).magenta(),
     };
 
-    let log_string = format!("{} {} {}", time_str, level_marker, record.args());
+    let log_string = if show_target {
+      format!(
+        "{} {} ({}) {}",
+        time_str,
+        level_marker,
+        record.target(),
+        record.args(),
+      )
+    } else {
+      format!("{} {} {}", time_str, level_marker, record.args())
+    };
 
     match destination {
       Destination::Stderr => {

src/rust/engine/src/externs/interface.rs

@@ -52,8 +52,9 @@ use std::sync::Arc;
 use std::time::Duration;
 
 use cpython::{
-  exc, py_class, py_exception, py_fn, py_module_initializer, NoArgs, PyClone, PyErr, PyList,
-  PyObject, PyResult as CPyResult, PyString, PyTuple, PyType, Python, PythonObject, ToPyObject,
+  exc, py_class, py_exception, py_fn, py_module_initializer, NoArgs, PyClone, PyDict, PyErr,
+  PyList, PyObject, PyResult as CPyResult, PyString, PyTuple, PyType, Python, PythonObject,
+  ToPyObject,
 };
 use futures::compat::Future01CompatExt;
 use futures::future::FutureExt;
@@ -64,6 +65,7 @@ use log::{self, debug, error, warn, Log};
 use logging::logger::PANTS_LOGGER;
 use logging::{Destination, Logger, PythonLogLevel};
 use rule_graph::{self, RuleGraph};
+use std::collections::hash_map::HashMap;
 use store::SnapshotOps;
 use task_executor::Executor;
 use tempfile::TempDir;
@@ -87,7 +89,10 @@ py_module_initializer!(native_engine, |py, m| {
   m.add(
     py,
     "init_logging",
-    py_fn!(py, init_logging(a: u64, b: bool, c: bool)),
+    py_fn!(
+      py,
+      init_logging(a: u64, b: bool, c: bool, d: bool, e: PyDict)
+    ),
   )?;
   m.add(
     py,
@@ -1685,12 +1690,29 @@ fn default_config_path(py: Python) -> CPyResult<String> {
 }
 
 fn init_logging(
-  _: Python,
+  py: Python,
   level: u64,
   show_rust_3rdparty_logs: bool,
   use_color: bool,
+  show_target: bool,
+  log_levels_by_target: PyDict,
 ) -> PyUnitResult {
-  Logger::init(level, show_rust_3rdparty_logs, use_color);
+  let log_levels_by_target = log_levels_by_target
+    .items(py)
+    .iter()
+    .map(|(k, v)| {
+      let k: String = k.extract(py).unwrap();
+      let v: u64 = v.extract(py).unwrap();
+      (k, v)
+    })
+    .collect::<HashMap<_, _>>();
+  Logger::init(
+    level,
+    show_rust_3rdparty_logs,
+    use_color,
+    show_target,
+    log_levels_by_target,
+  );
   Ok(None)
 }