Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Filter logs selectively #10414

Closed
wants to merge 7 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 13 additions & 2 deletions src/python/pants/engine/internals/native.py
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -124,8 +125,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,
log_show_rust_3rdparty: bool,
use_color: bool,
show_log_domain: bool,
log_domain_levels: Dict[str, LogLevel],
):
log_domain_levels_as_ints = {k: v.level for k, v in log_domain_levels.items()}
return self.lib.init_logging(
level, log_show_rust_3rdparty, use_color, show_log_domain, log_domain_levels_as_ints
)

def default_cache_path(self) -> str:
return cast(str, self.lib.default_cache_path())
Expand Down
41 changes: 33 additions & 8 deletions src/python/pants/init/logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@
import sys
import warnings
from logging import Formatter, Handler, LogRecord, StreamHandler
from typing import List, Optional, TextIO, Tuple
from typing import Dict, List, Optional, TextIO, Tuple

import pants.util.logging as pants_logging
from pants.base.exception_sink import ExceptionSink
Expand All @@ -22,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_log_domain: bool = False,
log_domain_levels: Dict[str, LogLevel] = {},
) -> None:
Native().init_rust_logging(
log_level.level, log_show_rust_3rdparty, use_color, show_log_domain, log_domain_levels
)


class NativeHandler(StreamHandler):
Expand All @@ -43,7 +51,9 @@ def __init__(
super().__init__(stream)
self.native = Native()
self.native_filename = native_filename
self.setLevel(log_level.level)
# Set to most granular level - rust logging code will take care of the filtering
# TODO: This should ask Rust for the minimum level to use since TRACE level generates too many logs.
self.setLevel(pants_logging.TRACE)

if stream:
try:
Expand All @@ -53,9 +63,7 @@ def __init__(
raise e

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()
Expand Down Expand Up @@ -116,6 +124,19 @@ def trace_fn(self, message, *args, **kwargs):
requests_logger.propagate = True


def get_log_domain_levels(global_bootstrap_options) -> Dict[str, LogLevel]:
raw_log_domain_levels = global_bootstrap_options.log_domain_levels
log_domain_levels: Dict[str, LogLevel] = {}
for key, value in raw_log_domain_levels.items():
if not isinstance(key, str):
raise ValueError("keys for log_domain_levels must be strings")
if not isinstance(value, str):
raise ValueError("values for log_domain_levels must be strings")
log_level = LogLevel[value.upper()]
log_domain_levels[key] = log_level
return log_domain_levels


def setup_logging(global_bootstrap_options):
"""Sets up logging for a pants run.

Expand All @@ -132,8 +153,12 @@ def setup_logging(global_bootstrap_options):

log_show_rust_3rdparty = global_bootstrap_options.log_show_rust_3rdparty
use_color = global_bootstrap_options.colors
show_log_domain = global_bootstrap_options.show_log_domain
log_domain_levels = get_log_domain_levels(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_log_domain, log_domain_levels
)
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)
Expand Down
26 changes: 25 additions & 1 deletion src/python/pants/option/global_options.py
Original file line number Diff line number Diff line change
Expand Up @@ -164,7 +164,31 @@ def register_bootstrap_options(cls, register):
default_rel_distdir = f"/{default_distdir_name}/"

register(
"-l", "--level", type=LogLevel, default=LogLevel.INFO, help="Set the logging level.",
"-l",
"--level",
type=LogLevel,
default=LogLevel.INFO,
help="Set the global logging level.",
)

register(
"--show-log-domain",
type=bool,
default=False,
advanced=True,
help="Display the log domain where a log message originates in that log message's output.",
)

register(
"--log-domain-levels",
type=dict,
default={},
advanced=True,
help=(
"Set a more specific logging level for one or more logging domains. A logging domain is "
"a particular subsection of Pants functionality. The logging level is one of "
"`warn`, `error`, `info`, `debug`, or `trace`."
),
)

register(
Expand Down
18 changes: 15 additions & 3 deletions src/python/pants/pantsd/pants_daemon.py
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,12 @@
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 clear_logging_handlers, init_rust_logger, setup_logging_to_file
from pants.init.logging import (
clear_logging_handlers,
get_log_domain_levels,
init_rust_logger,
setup_logging_to_file,
)
from pants.init.options_initializer import OptionsInitializer
from pants.option.option_value_container import OptionValueContainer
from pants.option.options import Options
Expand Down Expand Up @@ -211,8 +216,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)
bootstrap_options = self._bootstrap_options.for_global_scope()
use_color = bootstrap_options.colors
log_domain_levels = get_log_domain_levels(bootstrap_options)
init_rust_logger(
self._log_level,
self._log_show_rust_3rdparty,
use_color=use_color,
log_domain_levels=log_domain_levels,
)

level = self._log_level
ignores = self._bootstrap_options.for_global_scope().ignore_pants_warnings
Expand Down
86 changes: 77 additions & 9 deletions src/rust/engine/logging/src/logger.rs
Original file line number Diff line number Diff line change
@@ -1,9 +1,6 @@
// Copyright 2018 Pants project contributors (see CONTRIBUTORS.md).
// Licensed under the Apache License, Version 2.0 (see LICENSE).

use crate::PythonLogLevel;

use colored::*;
use std::cell::RefCell;
use std::collections::HashMap;
use std::convert::{TryFrom, TryInto};
Expand All @@ -14,13 +11,16 @@ use std::io::{stderr, Stderr, Write};
use std::path::PathBuf;
use std::sync::atomic::{AtomicBool, Ordering};

use colored::*;
use lazy_static::lazy_static;
use log::{debug, log, 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;

use crate::PythonLogLevel;

const TIME_FORMAT_STR: &str = "%H:%M:%S";

pub type StdioHandler = Box<dyn Fn(&str) -> Result<(), ()> + Send>;
Expand All @@ -34,7 +34,9 @@ pub struct PantsLogger {
stderr_log: Mutex<MaybeWriteLogger<Stderr>>,
use_color: AtomicBool,
show_rust_3rdparty_logs: AtomicBool,
show_log_domain: AtomicBool,
stderr_handlers: Mutex<HashMap<Uuid, StdioHandler>>,
log_level_filters: Mutex<RefCell<HashMap<String, log::LevelFilter>>>,
}

impl PantsLogger {
Expand All @@ -44,20 +46,46 @@ impl PantsLogger {
stderr_log: Mutex::new(MaybeWriteLogger::empty()),
show_rust_3rdparty_logs: AtomicBool::new(true),
use_color: AtomicBool::new(false),
show_log_domain: AtomicBool::new(false),
stderr_handlers: Mutex::new(HashMap::new()),
log_level_filters: Mutex::new(RefCell::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_log_domain: bool,
log_domain_levels: HashMap<String, u64>,
) {
let log_domain_levels = log_domain_levels
.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: log::LevelFilter = python_level.into();
set_max_level(level);
PANTS_LOGGER.use_color.store(use_color, Ordering::SeqCst);
PANTS_LOGGER
.show_log_domain
.store(show_log_domain, Ordering::SeqCst);
PANTS_LOGGER
.show_rust_3rdparty_logs
.store(show_rust_3rdparty_logs, Ordering::SeqCst);
PANTS_LOGGER
.log_level_filters
.lock()
.replace(log_domain_levels);
if set_logger(&*PANTS_LOGGER).is_err() {
debug!("Logging already initialized.");
}
Expand All @@ -78,7 +106,12 @@ impl PantsLogger {
.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.stderr_log.lock() = MaybeWriteLogger::new(
stderr(),
level.into(),
self.show_log_domain.load(Ordering::SeqCst),
self.log_level_filters.lock().borrow().clone(),
)
})
}

Expand Down Expand Up @@ -108,7 +141,12 @@ impl PantsLogger {
.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.pantsd_log.lock() = MaybeWriteLogger::new(
file,
level.into(),
self.show_log_domain.load(Ordering::SeqCst),
self.log_level_filters.lock().borrow().clone(),
);
fd
})
.map_err(|err| format!("Error opening pantsd logfile: {}", err))
Expand Down Expand Up @@ -181,6 +219,7 @@ impl Log for PantsLogger {
);

let level = record.level();
let show_log_domain = self.show_log_domain.load(Ordering::SeqCst);
let use_color = self.use_color.load(Ordering::SeqCst);

let level_marker = match level {
Expand All @@ -192,7 +231,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_log_domain {
format!(
"{} {} {} {}",
time_str,
level_marker,
record.target(),
record.args()
)
} else {
format!("{} {} {}", time_str, level_marker, record.args())
};

{
// We first try to output to all registered handlers. If there are none, or any of them
Expand Down Expand Up @@ -222,39 +271,58 @@ impl Log for PantsLogger {

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

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

pub fn new(writable: W, level: LevelFilter) -> MaybeWriteLogger<W> {
pub fn new(
writable: W,
level: LevelFilter,
show_log_domain: bool,
log_domain_filters: HashMap<String, 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.

let config = ConfigBuilder::new()
.set_time_format_str(TIME_FORMAT_STR)
.set_time_to_local(true)
.set_target_level(if show_log_domain {
LevelFilter::Error
} else {
LevelFilter::Off
})
.set_thread_level(LevelFilter::Off)
.set_level_padding(LevelPadding::Off)
.build();

MaybeWriteLogger {
level,
log_domain_filters,
inner: Some(WriteLogger::new(LevelFilter::max(), config, writable)),
}
}
}

impl<W: Write + Send + 'static> Log for MaybeWriteLogger<W> {
fn enabled(&self, metadata: &Metadata) -> bool {
metadata.level() <= self.level
let enabled_globally = metadata.level() <= self.level;
let enabled_for_log_domain = self
.log_domain_filters
.get(metadata.target())
.map(|lf| metadata.level() <= *lf)
.unwrap_or(false);
enabled_globally || enabled_for_log_domain
}

fn log(&self, record: &Record) {
Expand Down
Loading