From fd99e5d3538fdf71f4a56f5867a24cb56b633c23 Mon Sep 17 00:00:00 2001 From: Borja Lorente Date: Mon, 24 Dec 2018 14:08:23 +0100 Subject: [PATCH] Fix log prefixes, first attempt at missing logs --- src/python/pants/bin/pants_runner.py | 3 ++ src/python/pants/bin/remote_pants_runner.py | 22 ++++++--------- src/python/pants/engine/native.py | 4 +-- src/python/pants/init/logging.py | 31 +++++++++++++-------- src/python/pants/pantsd/pants_daemon.py | 2 +- src/rust/engine/logging/src/logger.rs | 11 ++++++-- src/rust/engine/src/lib.rs | 5 ++-- 7 files changed, 44 insertions(+), 34 deletions(-) diff --git a/src/python/pants/bin/pants_runner.py b/src/python/pants/bin/pants_runner.py index bf506cd91093..3df357bd3641 100644 --- a/src/python/pants/bin/pants_runner.py +++ b/src/python/pants/bin/pants_runner.py @@ -11,6 +11,7 @@ from pants.base.exception_sink import ExceptionSink from pants.bin.remote_pants_runner import RemotePantsRunner +from pants.init.logging import setup_logging_to_stderr from pants.option.options_bootstrapper import OptionsBootstrapper @@ -32,6 +33,8 @@ def __init__(self, exiter, args=None, env=None, start_time=None): self._start_time = start_time def run(self): + setup_logging_to_stderr(logger, 'TRACE') + # Register our exiter at the beginning of the run() method so that any code in this process from # this point onwards will use that exiter in the case of a fatal error. ExceptionSink.reset_exiter(self._exiter) diff --git a/src/python/pants/bin/remote_pants_runner.py b/src/python/pants/bin/remote_pants_runner.py index baa5fe412f38..27063150ea22 100644 --- a/src/python/pants/bin/remote_pants_runner.py +++ b/src/python/pants/bin/remote_pants_runner.py @@ -15,8 +15,7 @@ from pants.base.exception_sink import ExceptionSink from pants.console.stty_utils import STTYSettings -from pants.engine.native import Native -from pants.init.logging import setup_native_logging_to_stderr +from pants.init.logging import setup_logging_to_stderr from pants.java.nailgun_client import NailgunClient from pants.java.nailgun_protocol import NailgunProtocol from pants.pantsd.pants_daemon import PantsDaemon @@ -83,18 +82,6 @@ def handle_control_c(signum, frame): signal.signal(signal.SIGINT, existing_sigint_handler) signal.signal(signal.SIGQUIT, existing_sigquit_handler) - def _setup_logging(self): - """Sets up basic stdio logging for the thin client.""" - log_level = logging.getLevelName(self._bootstrap_options.for_global_scope().level.upper()) - - native = Native() - native_handler = setup_native_logging_to_stderr(log_level, native=native, prefix=type(self).__name__) - - root = logging.getLogger() - root.addHandler(native_handler) - - root.setLevel(log_level) - @staticmethod def _backoff(attempt): """Minimal backoff strategy for daemon restarts.""" @@ -107,6 +94,9 @@ def _run_pants_with_retry(self, pantsd_handle, retries=3): """ attempt = 1 while 1: + # TODO This should print to stderr with the thin client, but it doesn't. + # It goes through the ffi correctly, my guess is that we have deviated stderr somewhere + # without meaning to. logger.debug( 'connecting to pantsd on port {} (attempt {}/{})' .format(pantsd_handle.port, attempt, retries) @@ -185,6 +175,10 @@ def _restart_pantsd(self): def _maybe_launch_pantsd(self): return PantsDaemon.Factory.maybe_launch(options_bootstrapper=self._options_bootstrapper) + def _setup_logging(self): + log_level = logging.getLevelName(self._bootstrap_options.for_global_scope().level.upper()) + setup_logging_to_stderr(logger, log_level) + def run(self, args=None): self._setup_logging() pantsd_handle = self._maybe_launch_pantsd() diff --git a/src/python/pants/engine/native.py b/src/python/pants/engine/native.py index 939fa11eba52..ce53d3a03f38 100644 --- a/src/python/pants/engine/native.py +++ b/src/python/pants/engine/native.py @@ -643,8 +643,8 @@ def setup_pantsd_logger(self, log_file_path, level): def setup_stderr_logger(self, level): self.lib.setup_stderr_logger(level) - def write_log(self, msg, level): - self.lib.write_log(msg, level) + def write_log(self, msg, level, target): + self.lib.write_log(msg, level, target) def set_max_log_level(self, level): self.lib.set_max_log_level(level) diff --git a/src/python/pants/init/logging.py b/src/python/pants/init/logging.py index a28b96aef0c2..60b4c282376e 100644 --- a/src/python/pants/init/logging.py +++ b/src/python/pants/init/logging.py @@ -41,45 +41,52 @@ def _maybe_configure_extended_logging(logger): if logger.isEnabledFor(TRACE): _configure_requests_debug_logging() +def setup_logging_to_stderr(python_logger, level): + native = Native() + levelno = get_numeric_level(level) + handler = setup_native_logging_to_stderr(levelno, native, stream=sys.stderr) + native.set_max_log_level(levelno) + python_logger.addHandler(handler) + python_logger.setLevel(level) + def setup_logging_from_options(bootstrap_options): # N.B. quiet help says 'Squelches all console output apart from errors'. level = 'ERROR' if bootstrap_options.quiet else bootstrap_options.level.upper() # TODO This assumes creating a native is cheap and idempotent, which I think is true. native = Native() - return setup_logging(level, console_stream=sys.stderr, log_dir=bootstrap_options.logdir, native=native, prefix="LocalPantsRunner") + return setup_logging(level, console_stream=sys.stderr, log_dir=bootstrap_options.logdir, native=native) class NativeHandler(StreamHandler): - def __init__(self, level, native=None, prefix=None, stream=None): + def __init__(self, level, native=None, stream=None): super(NativeHandler, self).__init__(stream) self.native = native - self.prefix = prefix self.setLevel(level) def emit(self, record): - msg = ("[{}]: {}".format(self.prefix, self.format(record))).encode("utf-8") - self.native.write_log(msg, record.levelno) + msg = ("{}".format(self.format(record))).encode("utf-8") + self.native.write_log(msg, record.levelno, record.name.encode("utf-8")) -def setup_native_logging_to_pantsd_file(level, native, native_filename, prefix=None): +def setup_native_logging_to_pantsd_file(level, native, native_filename): try: native.setup_pantsd_logger(native_filename.encode("utf-8"), get_numeric_level(level)) except Exception as e: print("Error setting up pantsd logger: {}".format(e), file=sys.stderr) raise e - return NativeHandler(level, native, prefix) + return NativeHandler(level, native) -def setup_native_logging_to_stderr(level, native, prefix=None, stream=None): +def setup_native_logging_to_stderr(level, native, stream=None): try: native.setup_stderr_logger(get_numeric_level(level)) except Exception as e: print("Error setting up pantsd logger: {}".format(e), file=sys.stderr) raise e - return NativeHandler(level, native, prefix, stream) + return NativeHandler(level, native, stream) # TODO This function relies on logging._checkLevel, which is private. @@ -88,7 +95,7 @@ def setup_native_logging_to_stderr(level, native, prefix=None, stream=None): def get_numeric_level(level): return logging._checkLevel(level) -def setup_logging(level, console_stream=None, log_dir=None, scope=None, log_name=None, native=None, prefix=""): +def setup_logging(level, console_stream=None, log_dir=None, scope=None, log_name=None, native=None): """Configures logging for a given scope, by default the global scope. :param str level: The logging level to enable, must be one of the level names listed here: @@ -130,14 +137,14 @@ def trace(self, message, *args, **kwargs): logger.removeHandler(handler) if console_stream: - native_handler = setup_native_logging_to_stderr(level, native, prefix, stream=console_stream) + native_handler = setup_native_logging_to_stderr(level, native, stream=console_stream) logger.addHandler(native_handler) if log_dir: safe_mkdir(log_dir) log_filename = os.path.join(log_dir, log_name or 'pants.log') - native_handler = setup_native_logging_to_pantsd_file(level, native, log_filename, prefix=prefix) + native_handler = setup_native_logging_to_pantsd_file(level, native, log_filename) file_handler = native_handler logger.addHandler(native_handler) diff --git a/src/python/pants/pantsd/pants_daemon.py b/src/python/pants/pantsd/pants_daemon.py index 338c0c9507e7..3216d235eafd 100644 --- a/src/python/pants/pantsd/pants_daemon.py +++ b/src/python/pants/pantsd/pants_daemon.py @@ -287,7 +287,7 @@ def _pantsd_logging(self): # for further forks. with stdio_as(stdin_fd=-1, stdout_fd=-1, stderr_fd=-1): # Reinitialize logging for the daemon context. - result = setup_logging(self._log_level, log_dir=self._log_dir, log_name=self.LOG_NAME, native=self._native, prefix=type(self).__name__) + result = setup_logging(self._log_level, log_dir=self._log_dir, log_name=self.LOG_NAME, native=self._native) # Do a python-level redirect of stdout/stderr, which will not disturb `0,1,2`. # TODO: Consider giving these pipes/actual fds, in order to make them "deep" replacements diff --git a/src/rust/engine/logging/src/logger.rs b/src/rust/engine/logging/src/logger.rs index caa2be0d7aa0..22cf93765de7 100644 --- a/src/rust/engine/logging/src/logger.rs +++ b/src/rust/engine/logging/src/logger.rs @@ -68,9 +68,14 @@ impl Logger { }) } - pub fn log_from_python(&self, message: &str, python_level: u64) -> Result<(), String> { + pub fn log_from_python( + &self, + message: &str, + python_level: u64, + target: &str, + ) -> Result<(), String> { python_level.try_into_PythonLogLevel().map(|level| { - log!(level.into(), "{}", message); + log!(target: target, level.into(), "{}", message); }) } } @@ -112,7 +117,7 @@ impl MaybeWriteLogger { // have to create a new one every time we change the level of the outer // MaybeWriteLogger. MaybeWriteLogger { - level: level, + level, inner: Some(WriteLogger::new( LevelFilter::max(), Config::default(), diff --git a/src/rust/engine/src/lib.rs b/src/rust/engine/src/lib.rs index 86accf3eef7c..5250b2ee1aa5 100644 --- a/src/rust/engine/src/lib.rs +++ b/src/rust/engine/src/lib.rs @@ -796,10 +796,11 @@ pub extern "C" fn setup_stderr_logger(level: u64) { } #[no_mangle] -pub extern "C" fn write_log(msg: *const raw::c_char, level: u64) { +pub extern "C" fn write_log(msg: *const raw::c_char, level: u64, target: *const raw::c_char) { let message_str = unsafe { CStr::from_ptr(msg).to_string_lossy() }; + let target_str = unsafe { CStr::from_ptr(target).to_string_lossy() }; LOGGER - .log_from_python(message_str.borrow(), level) + .log_from_python(message_str.borrow(), level, target_str.borrow()) .expect("Error logging message"); }