diff --git a/src/python/pants/engine/internals/native.py b/src/python/pants/engine/internals/native.py index 3909497142f4..60391d1c17f7 100644 --- a/src/python/pants/engine/internals/native.py +++ b/src/python/pants/engine/internals/native.py @@ -133,11 +133,11 @@ def default_cache_path(self) -> str: def default_config_path(self) -> str: return cast(str, self.lib.default_config_path()) - def setup_pantsd_logger(self, log_file_path, level): - return self.lib.setup_pantsd_logger(log_file_path, level) + def setup_pantsd_logger(self, log_file_path): + return self.lib.setup_pantsd_logger(log_file_path) - def setup_stderr_logger(self, level): - return self.lib.setup_stderr_logger(level) + def setup_stderr_logger(self): + return self.lib.setup_stderr_logger() def write_log(self, msg: str, *, level: int, target: str): """Proxy a log message to the Rust logging faculties.""" diff --git a/src/python/pants/init/logging.py b/src/python/pants/init/logging.py index 162106c194ca..9dda2ffbd799 100644 --- a/src/python/pants/init/logging.py +++ b/src/python/pants/init/logging.py @@ -4,10 +4,9 @@ import http.client import logging import os -import sys import warnings from logging import Formatter, Handler, LogRecord, StreamHandler -from typing import List, Optional, TextIO, Tuple +from typing import List, Optional, Tuple import pants.util.logging as pants_logging from pants.base.exception_sink import ExceptionSink @@ -31,26 +30,15 @@ class NativeHandler(StreamHandler): method) and proxies logs to the Rust logging infrastructure.""" def __init__( - self, - log_level: LogLevel, - stream: Optional[TextIO] = None, - native_filename: Optional[str] = None, + self, log_level: LogLevel, native_filename: Optional[str] = None, ): - - if stream is not None and native_filename is not None: - raise RuntimeError("NativeHandler must output to either a stream or a file, not both") - - super().__init__(stream) + super().__init__(None) self.native = Native() self.native_filename = native_filename self.setLevel(log_level.level) - if stream: - try: - self.native.setup_stderr_logger(log_level.level) - except Exception as e: - print(f"Error setting up pantsd logger: {e!r}", file=sys.stderr) - raise e + if not self.native_filename: + self.native.setup_stderr_logger() def emit(self, record: LogRecord) -> None: self.native.write_log( @@ -61,10 +49,7 @@ def flush(self) -> None: self.native.flush_log() def __repr__(self) -> str: - return ( - f"NativeHandler(id={id(self)}, level={self.level}, filename={self.native_filename}, " - f"stream={self.stream})" - ) + return f"NativeHandler(id={id(self)}, level={self.level}, filename={self.native_filename}" class ExceptionFormatter(Formatter): @@ -150,7 +135,7 @@ def setup_logging_to_stderr( _common_logging_setup(level, warnings_filter_regexes) python_logger = logging.getLogger(None) - handler = NativeHandler(level, stream=sys.stderr) + handler = NativeHandler(level) handler.setFormatter(ExceptionFormatter()) python_logger.addHandler(handler) LogLevel.TRACE.set_level_for(python_logger) @@ -171,7 +156,7 @@ def setup_logging_to_file( safe_mkdir(log_dir) log_path = os.path.join(log_dir, log_filename) - fd = native.setup_pantsd_logger(log_path, level.level) + fd = native.setup_pantsd_logger(log_path) ExceptionSink.reset_interactive_output_stream(os.fdopen(os.dup(fd), "a")) handler = NativeHandler(level, native_filename=log_path) diff --git a/src/rust/engine/Cargo.lock b/src/rust/engine/Cargo.lock index f07c5d663d1a..6bbaa0975b64 100644 --- a/src/rust/engine/Cargo.lock +++ b/src/rust/engine/Cargo.lock @@ -601,26 +601,6 @@ dependencies = [ "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "dirs" -version = "2.0.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "cfg-if 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)", - "dirs-sys 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)", -] - -[[package]] -name = "dirs-sys" -version = "0.3.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "cfg-if 0.1.10 (registry+https://github.com/rust-lang/crates.io-index)", - "libc 0.2.71 (registry+https://github.com/rust-lang/crates.io-index)", - "redox_users 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)", - "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "double-checked-cell-async" version = "2.0.2" @@ -1447,7 +1427,6 @@ dependencies = [ "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", "num_enum 0.4.3 (registry+https://github.com/rust-lang/crates.io-index)", "parking_lot 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)", - "simplelog 0.7.4 (registry+https://github.com/rust-lang/crates.io-index)", "tokio 0.2.20 (registry+https://github.com/rust-lang/crates.io-index)", "uuid 0.7.4 (registry+https://github.com/rust-lang/crates.io-index)", ] @@ -2668,16 +2647,6 @@ dependencies = [ "libc 0.2.71 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "simplelog" -version = "0.7.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "chrono 0.4.11 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", - "term 0.6.1 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "slab" version = "0.4.2" @@ -2885,15 +2854,6 @@ dependencies = [ "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "term" -version = "0.6.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "dirs 2.0.2 (registry+https://github.com/rust-lang/crates.io-index)", - "winapi 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "termcolor" version = "1.1.0" @@ -3560,8 +3520,6 @@ dependencies = [ "checksum digest 0.9.0 (registry+https://github.com/rust-lang/crates.io-index)" = "d3dd60d1080a57a05ab032377049e0591415d2b31afd7028356dbf3cc6dcb066" "checksum dir-diff 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "2860407d7d7e2e004bb2128510ad9e8d669e76fa005ccf567977b5d71b8b4a0b" "checksum dirs 1.0.5 (registry+https://github.com/rust-lang/crates.io-index)" = "3fd78930633bd1c6e35c4b42b1df7b0cbc6bc191146e512bb3bedf243fcc3901" -"checksum dirs 2.0.2 (registry+https://github.com/rust-lang/crates.io-index)" = "13aea89a5c93364a98e9b37b2fa237effbb694d5cfe01c5b70941f7eb087d5e3" -"checksum dirs-sys 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)" = "afa0b23de8fd801745c471deffa6e12d248f962c9fd4b4c33787b055599bde7b" "checksum double-checked-cell-async 2.0.2 (registry+https://github.com/rust-lang/crates.io-index)" = "6f22db4315075554331c4976a70d10d2d07192d1df01e9e68553bb632c3fa157" "checksum dtoa 0.4.5 (registry+https://github.com/rust-lang/crates.io-index)" = "4358a9e11b9a09cf52383b451b49a169e8d797b68aa02301ff586d70d9661ea3" "checksum either 1.5.3 (registry+https://github.com/rust-lang/crates.io-index)" = "bb1f6b1ce1c140482ea30ddd3335fc0024ac7ee112895426e0a629a6c20adfe3" @@ -3759,7 +3717,6 @@ dependencies = [ "checksum shell-quote 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "4fb975283e6af8d3d691ddcefdca3a4dffe369167746d22fd993205e1e0c0de0" "checksum shlex 0.1.1 (registry+https://github.com/rust-lang/crates.io-index)" = "7fdf1b9db47230893d76faad238fd6097fd6d6a9245cd7a4d90dbd639536bbd2" "checksum signal-hook-registry 1.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "94f478ede9f64724c5d173d7bb56099ec3e2d9fc2774aac65d34b8b890405f41" -"checksum simplelog 0.7.4 (registry+https://github.com/rust-lang/crates.io-index)" = "05a3e303ace6adb0a60a9e9e2fbc6a33e1749d1e43587e2125f7efa9c5e107c5" "checksum slab 0.4.2 (registry+https://github.com/rust-lang/crates.io-index)" = "c111b5bd5695e56cffe5129854aa230b39c93a305372fdbb2668ca2394eea9f8" "checksum smallvec 0.6.13 (registry+https://github.com/rust-lang/crates.io-index)" = "f7b0758c52e15a8b5e3691eae6cc559f08eee9406e548a4477ba4e67770a82b6" "checksum smallvec 1.4.0 (registry+https://github.com/rust-lang/crates.io-index)" = "c7cb5678e1615754284ec264d9bb5b4c27d2018577fd90ac0ceb578591ed5ee4" @@ -3777,7 +3734,6 @@ dependencies = [ "checksum tar 0.4.26 (registry+https://github.com/rust-lang/crates.io-index)" = "b3196bfbffbba3e57481b6ea32249fbaf590396a52505a2615adbb79d9d826d3" "checksum tempdir 0.3.7 (registry+https://github.com/rust-lang/crates.io-index)" = "15f2b5fb00ccdf689e0149d1b1b3c03fead81c2b37735d812fa8bddbbf41b6d8" "checksum tempfile 3.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7a6e24d9338a0a5be79593e2fa15a648add6138caa803e2d5bc782c371732ca9" -"checksum term 0.6.1 (registry+https://github.com/rust-lang/crates.io-index)" = "c0863a3345e70f61d613eab32ee046ccd1bcc5f9105fe402c61fcd0c13eeb8b5" "checksum termcolor 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f" "checksum termios 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "6f0fcee7b24a25675de40d5bb4de6e41b0df07bc9856295e7e2b3a3600c400c2" "checksum textwrap 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)" = "d326610f408c7a4eb6f51c37c330e496b08506c9457c9d34287ecc38809fb060" diff --git a/src/rust/engine/logging/Cargo.toml b/src/rust/engine/logging/Cargo.toml index 71e6e81a7ac7..81d1527644d3 100644 --- a/src/rust/engine/logging/Cargo.toml +++ b/src/rust/engine/logging/Cargo.toml @@ -12,9 +12,7 @@ lazy_static = "1" log = "0.4" num_enum = "0.4" parking_lot = "0.11" -simplelog = "0.7.4" -# TODO: See #10291. -tokio = { version = "=0.2.20", features = ["rt-util"] } +tokio = { version = "=0.2.20", features = ["rt-util"] } # TODO: see https://github.com/pantsbuild/pants/issues/10291 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 19dab25e977a..84a8e1c93fb7 100644 --- a/src/rust/engine/logging/src/logger.rs +++ b/src/rust/engine/logging/src/logger.rs @@ -1,6 +1,5 @@ // Copyright 2018 Pants project contributors (see CONTRIBUTORS.md). // Licensed under the Apache License, Version 2.0 (see LICENSE). - use crate::PythonLogLevel; use colored::*; @@ -10,14 +9,13 @@ use std::convert::{TryFrom, TryInto}; use std::fs::File; use std::fs::OpenOptions; use std::future::Future; -use std::io::{stderr, Stderr, Write}; +use std::io::Write; use std::path::PathBuf; 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 log::{debug, log, max_level, set_logger, set_max_level, LevelFilter, Log, Metadata, Record}; use parking_lot::Mutex; -use simplelog::{ConfigBuilder, LevelPadding, WriteLogger}; use tokio::task_local; use uuid::Uuid; @@ -30,8 +28,7 @@ lazy_static! { } pub struct PantsLogger { - pantsd_log: Mutex>, - stderr_log: Mutex>, + log_file: Mutex>, use_color: AtomicBool, show_rust_3rdparty_logs: AtomicBool, stderr_handlers: Mutex>, @@ -40,8 +37,7 @@ pub struct PantsLogger { impl PantsLogger { pub fn new() -> PantsLogger { PantsLogger { - pantsd_log: Mutex::new(MaybeWriteLogger::empty()), - stderr_log: Mutex::new(MaybeWriteLogger::empty()), + log_file: Mutex::new(None), show_rust_3rdparty_logs: AtomicBool::new(true), use_color: AtomicBool::new(false), stderr_handlers: Mutex::new(HashMap::new()), @@ -52,7 +48,7 @@ impl PantsLogger { let max_python_level: Result = max_level.try_into(); match max_python_level { Ok(python_level) => { - let level: log::LevelFilter = python_level.into(); + let level: LevelFilter = python_level.into(); set_max_level(level); PANTS_LOGGER.use_color.store(use_color, Ordering::SeqCst); PANTS_LOGGER @@ -66,22 +62,6 @@ impl PantsLogger { }; } - fn maybe_increase_global_verbosity(&self, new_level: log::LevelFilter) { - if log::max_level() < new_level { - set_max_level(new_level); - } - } - - pub fn set_stderr_logger(&self, python_level: u64) -> Result<(), String> { - python_level - .try_into() - .map_err(|err| format!("{}", err)) - .map(|level: PythonLogLevel| { - self.maybe_increase_global_verbosity(level.into()); - *self.stderr_log.lock() = MaybeWriteLogger::new(stderr(), level.into()) - }) - } - /// /// Set up a file logger which logs at python_level to log_file_path. /// Returns the file descriptor of the log file. @@ -90,29 +70,24 @@ impl PantsLogger { pub fn set_pantsd_logger( &self, log_file_path: PathBuf, - python_level: u64, ) -> Result { use std::os::unix::io::AsRawFd; - python_level - .try_into() - .map_err(|err| format!("{}", err)) - .and_then(|level: PythonLogLevel| { - { - // Maybe close open file by dropping the existing logger - *self.pantsd_log.lock() = MaybeWriteLogger::empty(); - } - OpenOptions::new() - .create(true) - .append(true) - .open(log_file_path) - .map(|file| { - let fd = file.as_raw_fd(); - self.maybe_increase_global_verbosity(level.into()); - *self.pantsd_log.lock() = MaybeWriteLogger::new(file, level.into()); - fd - }) - .map_err(|err| format!("Error opening pantsd logfile: {}", err)) + + { + // Maybe close open file by dropping the existing file handle + *self.log_file.lock() = None; + } + + OpenOptions::new() + .create(true) + .append(true) + .open(log_file_path) + .map(|file| { + let raw_fd = file.as_raw_fd(); + *self.log_file.lock() = Some(file); + raw_fd }) + .map_err(|err| format!("Error opening pantsd logfile: {}", err)) } /// log_from_python is only used in the Python FFI, which in turn is only called within the @@ -142,11 +117,11 @@ impl PantsLogger { } impl Log for PantsLogger { - fn enabled(&self, _metadata: &Metadata) -> bool { + fn enabled(&self, metadata: &Metadata) -> bool { // Individual log levels are handled by each sub-logger, // And a global filter is applied to set_max_level. // No need to filter here. - true + metadata.level() <= max_level() } fn log(&self, record: &Record) { @@ -171,107 +146,62 @@ impl Log for PantsLogger { } let destination = get_destination(); - match destination { - Destination::Stderr => { - let cur_date = chrono::Local::now(); - let time_str = format!( - "{}.{:02}", - cur_date.format(TIME_FORMAT_STR), - cur_date.time().nanosecond() / 10_000_000 // two decimal places of precision - ); - - let level = record.level(); - let use_color = self.use_color.load(Ordering::SeqCst); - - let level_marker = match level { - _ if !use_color => format!("[{}]", level).normal().clear(), - Level::Info => format!("[{}]", level).normal(), - Level::Error => format!("[{}]", level).red(), - Level::Warn => format!("[{}]", level).red(), - Level::Debug => format!("[{}]", level).green(), - Level::Trace => format!("[{}]", level).magenta(), - }; + let cur_date = chrono::Local::now(); + let time_str = format!( + "{}.{:02}", + cur_date.format(TIME_FORMAT_STR), + cur_date.time().nanosecond() / 10_000_000 // two decimal places of precision + ); + + let level = record.level(); + let destination_is_file = match destination { + Destination::Pantsd => true, + Destination::Stderr => false, + }; + let use_color = self.use_color.load(Ordering::SeqCst) && (!destination_is_file); + + let level_marker = match level { + _ if !use_color => format!("[{}]", level).normal().clear(), + Level::Info => format!("[{}]", level).normal(), + Level::Error => format!("[{}]", level).red(), + Level::Warn => format!("[{}]", level).red(), + Level::Debug => format!("[{}]", level).green(), + Level::Trace => format!("[{}]", level).magenta(), + }; - let log_string = format!("{} {} {}", time_str, level_marker, record.args()); + let log_string = format!("{} {} {}", time_str, level_marker, record.args()); - { - // We first try to output to all registered handlers. If there are none, or any of them - // fail, then we fallback to sending directly to stderr. - let handlers_map = self.stderr_handlers.lock(); - let mut any_handler_failed = false; - for callback in handlers_map.values() { - let handler_res = callback(&log_string); - if handler_res.is_err() { - any_handler_failed = true; - } + match destination { + Destination::Stderr => { + // We first try to output to all registered handlers. If there are none, or any of them + // fail, then we fallback to sending directly to stderr. + let handlers_map = self.stderr_handlers.lock(); + let mut any_handler_failed = false; + for callback in handlers_map.values() { + let handler_res = callback(&log_string); + if handler_res.is_err() { + any_handler_failed = true; } - if handlers_map.len() == 0 || any_handler_failed { - self.stderr_log.lock().log(record); + } + if handlers_map.len() == 0 || any_handler_failed { + eprintln!("{}", log_string); + } + } + Destination::Pantsd => { + let mut maybe_file = self.log_file.lock(); + if let Some(ref mut file) = *maybe_file { + match writeln!(file, "{}", log_string) { + Ok(()) => (), + Err(e) => { + eprintln!("Error writing to log file: {}", e); + } } } } - Destination::Pantsd => self.pantsd_log.lock().log(record), - } - } - - fn flush(&self) { - self.stderr_log.lock().flush(); - self.pantsd_log.lock().flush(); - } -} - -struct MaybeWriteLogger { - level: LevelFilter, - inner: Option>>, -} - -impl MaybeWriteLogger { - pub fn empty() -> MaybeWriteLogger { - MaybeWriteLogger { - level: LevelFilter::Off, - inner: None, - } - } - - pub fn new(writable: W, level: LevelFilter) -> MaybeWriteLogger { - // We initialize the inner WriteLogger with no filters so that we don't - // have to create a new one every time we change the level of the outer - // MaybeWriteLogger. - - let config = ConfigBuilder::new() - .set_time_format_str(TIME_FORMAT_STR) - .set_time_to_local(true) - .set_thread_level(LevelFilter::Off) - .set_level_padding(LevelPadding::Off) - .set_target_level(LevelFilter::Off) - .build(); - - MaybeWriteLogger { - level, - inner: Some(WriteLogger::new(LevelFilter::max(), config, writable)), - } - } -} - -impl Log for MaybeWriteLogger { - fn enabled(&self, metadata: &Metadata) -> bool { - metadata.level() <= self.level - } - - fn log(&self, record: &Record) { - if !self.enabled(record.metadata()) { - return; - } - if let Some(ref logger) = self.inner { - logger.log(record); } } - fn flush(&self) { - if let Some(ref logger) = self.inner { - logger.flush(); - } - } + fn flush(&self) {} } /// diff --git a/src/rust/engine/src/externs/interface.rs b/src/rust/engine/src/externs/interface.rs index bda22f167969..691ae0dfe4c6 100644 --- a/src/rust/engine/src/externs/interface.rs +++ b/src/rust/engine/src/externs/interface.rs @@ -92,13 +92,9 @@ py_module_initializer!(native_engine, |py, m| { m.add( py, "setup_pantsd_logger", - py_fn!(py, setup_pantsd_logger(a: String, b: u64)), - )?; - m.add( - py, - "setup_stderr_logger", - py_fn!(py, setup_stderr_logger(a: u64)), + py_fn!(py, setup_pantsd_logger(a: String)), )?; + m.add(py, "setup_stderr_logger", py_fn!(py, setup_stderr_logger()))?; m.add(py, "flush_log", py_fn!(py, flush_log()))?; m.add( py, @@ -1673,21 +1669,18 @@ fn init_logging( Ok(None) } -fn setup_pantsd_logger(py: Python, log_file: String, level: u64) -> CPyResult { +fn setup_pantsd_logger(py: Python, log_file: String) -> CPyResult { logging::set_thread_destination(Destination::Pantsd); let path = PathBuf::from(log_file); PANTS_LOGGER - .set_pantsd_logger(path, level) + .set_pantsd_logger(path) .map(i64::from) .map_err(|e| PyErr::new::(py, (e,))) } -fn setup_stderr_logger(_: Python, level: u64) -> PyUnitResult { +fn setup_stderr_logger(_: Python) -> PyUnitResult { logging::set_thread_destination(Destination::Stderr); - PANTS_LOGGER - .set_stderr_logger(level) - .expect("Error setting up STDERR logger"); Ok(None) } diff --git a/tests/python/pants_test/init/test_logging.py b/tests/python/pants_test/init/test_logging.py index 88964a4cdc1c..59f0279c05f0 100644 --- a/tests/python/pants_test/init/test_logging.py +++ b/tests/python/pants_test/init/test_logging.py @@ -22,9 +22,7 @@ def setUpClass(cls) -> None: # `init_rust_logging` must never be called more than once. The Rust logger is global and static, # and initializing it twice in the same test class results in a SIGABRT. Native().init_rust_logging( - # We set the level to the least verbose possible, as individual tests will increase the - # verbosity as necessary. - level=LogLevel.ERROR.level, + level=LogLevel.INFO.level, # Tests assume a log level of INFO log_show_rust_3rdparty=False, use_color=False, )