Skip to content

Commit

Permalink
Fix Rust 3rdparty logs showing up with --dynamic-ui (#10640)
Browse files Browse the repository at this point in the history
Before, if `--dynamic-ui` was set and `-ldebug`, we would get messages like:

```
18:51:12.29 [DEBUG] glob converted to regex: Glob { glob: "**/.*", re: "(?-u)^(?:/?|.*/)\\.[^/]*$", opts: GlobOptions { case_insensitive: false, literal_separator: true, backslash_escape: true }, tokens: Tokens([RecursivePrefix, Literal('.'), ZeroOrMore]) }
18:51:12.29 [DEBUG] built glob set; 0 literals, 2 basenames, 1 extensions, 0 prefixes, 0 suffixes, 0 required extensions, 1 regexes
```

This was because filtering of 3rd party modules happening in `MaybeWriteLogger`, which isn't used by the dynamic UI.

This also renames the logger variables to be less generic so that we can more clearly distinguish between our own abstractions vs. upstream crates.

[ci skip-build-wheels]
  • Loading branch information
Eric-Arellano authored Aug 18, 2020
1 parent 2ca63be commit 5d7600d
Show file tree
Hide file tree
Showing 4 changed files with 44 additions and 56 deletions.
2 changes: 1 addition & 1 deletion src/rust/engine/logging/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ pub mod logger;

pub use logger::{get_destination, scope_task_destination, set_thread_destination, Destination};

pub type Logger = logger::Logger;
pub type Logger = logger::PantsLogger;

use num_enum::TryFromPrimitive;

Expand Down
84 changes: 36 additions & 48 deletions src/rust/engine/logging/src/logger.rs
Original file line number Diff line number Diff line change
Expand Up @@ -26,24 +26,24 @@ const TIME_FORMAT_STR: &str = "%H:%M:%S";
pub type StdioHandler = Box<dyn Fn(&str) -> Result<(), ()> + Send>;

lazy_static! {
pub static ref LOGGER: Logger = Logger::new();
pub static ref PANTS_LOGGER: PantsLogger = PantsLogger::new();
}

pub struct Logger {
pub struct PantsLogger {
pantsd_log: Mutex<MaybeWriteLogger<File>>,
stderr_log: Mutex<MaybeWriteLogger<Stderr>>,
use_color: AtomicBool,
show_rust_3rdparty_logs: AtomicBool,
stderr_handlers: Mutex<HashMap<Uuid, StdioHandler>>,
}

impl Logger {
pub fn new() -> Logger {
Logger {
impl PantsLogger {
pub fn new() -> PantsLogger {
PantsLogger {
pantsd_log: Mutex::new(MaybeWriteLogger::empty()),
stderr_log: Mutex::new(MaybeWriteLogger::empty()),
show_rust_3rdparty_logs: AtomicBool::new(true),
use_color: AtomicBool::new(true),
use_color: AtomicBool::new(false),
stderr_handlers: Mutex::new(HashMap::new()),
}
}
Expand All @@ -54,15 +54,15 @@ impl Logger {
Ok(python_level) => {
let level: log::LevelFilter = python_level.into();
set_max_level(level);
LOGGER.use_color.store(use_color, Ordering::SeqCst);
LOGGER
PANTS_LOGGER.use_color.store(use_color, Ordering::SeqCst);
PANTS_LOGGER
.show_rust_3rdparty_logs
.store(show_rust_3rdparty_logs, Ordering::SeqCst);
if set_logger(&*LOGGER).is_err() {
if set_logger(&*PANTS_LOGGER).is_err() {
debug!("Logging already initialized.");
}
}
Err(err) => panic!("Unrecognised log level from python: {}: {}", max_level, err),
Err(err) => panic!("Unrecognised log level from Python: {}: {}", max_level, err),
};
}

Expand All @@ -78,11 +78,7 @@ impl Logger {
.map_err(|err| format!("{}", err))
.map(|level: PythonLogLevel| {
self.maybe_increase_global_verbosity(level.into());
*self.stderr_log.lock() = MaybeWriteLogger::new(
stderr(),
level.into(),
self.show_rust_3rdparty_logs.load(Ordering::SeqCst),
)
*self.stderr_log.lock() = MaybeWriteLogger::new(stderr(), level.into())
})
}

Expand Down Expand Up @@ -112,11 +108,7 @@ impl Logger {
.map(|file| {
let fd = file.as_raw_fd();
self.maybe_increase_global_verbosity(level.into());
*self.pantsd_log.lock() = MaybeWriteLogger::new(
file,
level.into(),
self.show_rust_3rdparty_logs.load(Ordering::SeqCst),
);
*self.pantsd_log.lock() = MaybeWriteLogger::new(file, level.into());
fd
})
.map_err(|err| format!("Error opening pantsd logfile: {}", err))
Expand Down Expand Up @@ -149,7 +141,7 @@ impl Logger {
}
}

impl Log for Logger {
impl Log for PantsLogger {
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.
Expand All @@ -160,6 +152,24 @@ impl Log for Logger {
fn log(&self, record: &Record) {
use chrono::Timelike;
use log::Level;

let mut should_log = self.show_rust_3rdparty_logs.load(Ordering::SeqCst);
if !should_log {
if let Some(ref module_path) = record.module_path() {
for pants_package in super::pants_packages::PANTS_PACKAGE_NAMES {
if &module_path.split("::").next().unwrap() == pants_package {
should_log = true;
break;
}
}
} else {
should_log = true;
}
}
if !should_log {
return;
}

let destination = get_destination();
match destination {
Destination::Stderr => {
Expand All @@ -185,12 +195,13 @@ impl Log for Logger {
let log_string = format!("{} {} {}", time_str, level_marker, record.args());

{
// If there are no handlers, or sending to any of the handlers failed, send to stderr
// directly.
// 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() {
if callback(&log_string).is_err() {
let handler_res = callback(&log_string);
if handler_res.is_err() {
any_handler_failed = true;
}
}
Expand All @@ -211,24 +222,18 @@ impl Log for Logger {

struct MaybeWriteLogger<W: Write + Send + 'static> {
level: LevelFilter,
show_rust_3rdparty_logs: bool,
inner: Option<Box<WriteLogger<W>>>,
}

impl<W: Write + Send + 'static> MaybeWriteLogger<W> {
pub fn empty() -> MaybeWriteLogger<W> {
MaybeWriteLogger {
level: LevelFilter::Off,
show_rust_3rdparty_logs: true,
inner: None,
}
}

pub fn new(
writable: W,
level: LevelFilter,
show_rust_3rdparty_logs: bool,
) -> MaybeWriteLogger<W> {
pub fn new(writable: W, level: LevelFilter) -> MaybeWriteLogger<W> {
// 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.
Expand All @@ -242,7 +247,6 @@ impl<W: Write + Send + 'static> MaybeWriteLogger<W> {

MaybeWriteLogger {
level,
show_rust_3rdparty_logs,
inner: Some(WriteLogger::new(LevelFilter::max(), config, writable)),
}
}
Expand All @@ -257,22 +261,6 @@ impl<W: Write + Send + 'static> Log for MaybeWriteLogger<W> {
if !self.enabled(record.metadata()) {
return;
}
let mut should_log = self.show_rust_3rdparty_logs;
if !self.show_rust_3rdparty_logs {
if let Some(ref module_path) = record.module_path() {
for pants_package in super::pants_packages::PANTS_PACKAGE_NAMES {
if &module_path.split("::").next().unwrap() == pants_package {
should_log = true;
break;
}
}
} else {
should_log = true;
}
}
if !should_log {
return;
}
if let Some(ref logger) = self.inner {
logger.log(record);
}
Expand Down
8 changes: 4 additions & 4 deletions src/rust/engine/src/externs/interface.rs
Original file line number Diff line number Diff line change
Expand Up @@ -61,7 +61,7 @@ use futures::future::{self as future03, TryFutureExt};
use futures01::Future;
use hashing::{Digest, EMPTY_DIGEST};
use log::{self, debug, error, warn, Log};
use logging::logger::LOGGER;
use logging::logger::PANTS_LOGGER;
use logging::{Destination, Logger, PythonLogLevel};
use rule_graph::{self, RuleGraph};
use store::SnapshotOps;
Expand Down Expand Up @@ -1658,15 +1658,15 @@ fn setup_pantsd_logger(py: Python, log_file: String, level: u64) -> CPyResult<i6
logging::set_thread_destination(Destination::Pantsd);

let path = PathBuf::from(log_file);
LOGGER
PANTS_LOGGER
.set_pantsd_logger(path, level)
.map(i64::from)
.map_err(|e| PyErr::new::<exc::Exception, _>(py, (e,)))
}

fn setup_stderr_logger(_: Python, level: u64) -> PyUnitResult {
logging::set_thread_destination(Destination::Stderr);
LOGGER
PANTS_LOGGER
.set_stderr_logger(level)
.expect("Error setting up STDERR logger");
Ok(None)
Expand Down Expand Up @@ -1717,7 +1717,7 @@ fn teardown_dynamic_ui(

fn flush_log(py: Python) -> PyUnitResult {
py.allow_threads(|| {
LOGGER.flush();
PANTS_LOGGER.flush();
Ok(None)
})
}
Expand Down
6 changes: 3 additions & 3 deletions src/rust/engine/ui/src/console_ui.rs
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ use indexmap::IndexMap;
use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget, ProgressStyle};
use uuid::Uuid;

use logging::logger::{StdioHandler, LOGGER};
use logging::logger::{StdioHandler, PANTS_LOGGER};
use task_executor::Executor;
use workunit_store::WorkunitStore;

Expand Down Expand Up @@ -192,7 +192,7 @@ impl ConsoleUI {
self.instance = Some(Instance {
tasks_to_display: IndexMap::new(),
multi_progress_task,
logger_handle: LOGGER.register_stderr_handler(stderr_handler),
logger_handle: PANTS_LOGGER.register_stderr_handler(stderr_handler),
bars,
});
Ok(())
Expand All @@ -203,7 +203,7 @@ impl ConsoleUI {
///
pub fn teardown(&mut self) -> impl Future<Output = Result<(), String>> {
if let Some(instance) = self.instance.take() {
LOGGER.deregister_stderr_handler(instance.logger_handle);
PANTS_LOGGER.deregister_stderr_handler(instance.logger_handle);
instance
.multi_progress_task
.map_err(|e| format!("Failed to render UI: {}", e))
Expand Down

0 comments on commit 5d7600d

Please sign in to comment.