Fix log prefixes, first attempt at missing logs

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)

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()

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)

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)
 

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

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<W: Write + Send + 'static> MaybeWriteLogger<W> {
     // 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(),

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");
 }