[V2-UI] Move logging to Rust (#6817)

### Problem

Currently, Rust calls Python through FFI to handle logging. As we move to the V2 UI, we would like to make the reverse happen, where the V2 engine logs to the UI.

### Solution

The Rust code owns logging (which the Python code can forward to) instead of the other way around.

Note that this PR changes some logging formats (adding timestamps, adding PIDs, and possibly a few other minor changes).

src/python/pants/base/exception_sink.py

@@ -122,7 +122,7 @@ def reset_log_location(cls, new_log_location):
       `cls._shared_error_fileobj`.
     OS state:
     - May create a new directory.
-    - Overwrites signal handlers for many fatal and non-fatal signals.
+    - Overwrites signal handlers for many fatal and non-fatal signals (but not SIGUSR2).
 
     :raises: :class:`ExceptionSink.ExceptionSinkError` if the directory does not exist or is not
              writable.
@@ -167,7 +167,11 @@ def reset_exiter(cls, exiter):
     sys.excepthook = cls._log_unhandled_exception_and_exit
 
   @classmethod
-  def reset_interactive_output_stream(cls, interactive_output_stream):
+  def reset_interactive_output_stream(
+    cls,
+    interactive_output_stream,
+    override_faulthandler_destination=True
+  ):
     """
     Class state:
     - Overwrites `cls._interactive_output_stream`.
@@ -180,8 +184,9 @@ def reset_interactive_output_stream(cls, interactive_output_stream):
     try:
       # NB: mutate process-global state!
       # This permits a non-fatal `kill -31 <pants pid>` for stacktrace retrieval.
-      faulthandler.register(signal.SIGUSR2, interactive_output_stream,
-                            all_threads=True, chain=False)
+      if override_faulthandler_destination:
+        faulthandler.register(signal.SIGUSR2, interactive_output_stream,
+                              all_threads=True, chain=False)
       # NB: mutate the class variables!
       cls._interactive_output_stream = interactive_output_stream
     except ValueError:

src/python/pants/base/exiter.py

@@ -6,6 +6,7 @@
 
 import logging
 import sys
+import traceback
 from builtins import object
 
 from future.utils import PY3
@@ -70,6 +71,12 @@ def exit(self, result=PANTS_SUCCEEDED_EXIT_CODE, msg=None, out=None):
       except Exception as e:
         # If the file is already closed, or any other error occurs, just log it and continue to
         # exit.
+        if msg:
+          logger.warning("Encountered error when trying to log this message: {}".format(msg))
+          # In pantsd, this won't go anywhere, because there's really nowhere for us to log if we
+          # can't log :(
+          # Not in pantsd, this will end up in sys.stderr.
+          traceback.print_stack()
         logger.exception(e)
     self._exit(result)
 

src/python/pants/bin/local_pants_runner.py

@@ -140,8 +140,8 @@ def create(cls, exiter, args, env, target_roots=None, daemon_graph_session=None,
     options, build_config, options_bootstrapper = cls.parse_options(
       args,
       env,
-      True,
-      options_bootstrapper
+      setup_logging=True,
+      options_bootstrapper=options_bootstrapper,
     )
     global_options = options.for_global_scope()
 

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 init_rust_logger, setup_logging_to_stderr
 from pants.option.options_bootstrapper import OptionsBootstrapper
 
 
@@ -31,6 +32,11 @@ def __init__(self, exiter, args=None, env=None, start_time=None):
     self._env = env or os.environ
     self._start_time = start_time
 
+  def _enable_rust_logging(self, global_bootstrap_options):
+    levelname = global_bootstrap_options.level.upper()
+    init_rust_logger(levelname)
+    setup_logging_to_stderr(logging.getLogger(None), levelname)
+
   def run(self):
     # 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.
@@ -40,6 +46,10 @@ def run(self):
     bootstrap_options = options_bootstrapper.bootstrap_options
     global_bootstrap_options = bootstrap_options.for_global_scope()
 
+    # We enable Rust logging here,
+    # and everything before it will be routed through regular Python logging.
+    self._enable_rust_logging(global_bootstrap_options)
+
     ExceptionSink.reset_should_print_backtrace_to_terminal(global_bootstrap_options.print_exception_stacktrace)
     ExceptionSink.reset_log_location(global_bootstrap_options.pants_workdir)
 

src/python/pants/bin/remote_pants_runner.py

@@ -95,19 +95,6 @@ def _trapped_signals(self, client):
     with ExceptionSink.trapped_signals(signal_handler):
       yield
 
-  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())
-
-    formatter = logging.Formatter('%(levelname)s] %(message)s')
-    handler = logging.StreamHandler(sys.stderr)
-    handler.setLevel(log_level)
-    handler.setFormatter(formatter)
-
-    root = logging.getLogger()
-    root.setLevel(log_level)
-    root.addHandler(handler)
-
   @staticmethod
   def _backoff(attempt):
     """Minimal backoff strategy for daemon restarts."""
@@ -200,6 +187,5 @@ def _maybe_launch_pantsd(self):
     return PantsDaemon.Factory.maybe_launch(options_bootstrapper=self._options_bootstrapper)
 
   def run(self, args=None):
-    self._setup_logging()
     pantsd_handle = self._maybe_launch_pantsd()
     self._run_pants_with_retry(pantsd_handle)

src/python/pants/engine/native.py

@@ -271,12 +271,6 @@ def call(cls, c, func, args):
 
     return PyResult(is_throw, c.to_value(val))
 
-  @_extern_decl('void', ['ExternContext*', 'uint8_t', 'uint8_t*', 'uint64_t'])
-  def extern_log(self, context_handle, level, msg_ptr, msg_len):
-    """Given a log level and utf8 message string, log it."""
-    msg = bytes(self._ffi.buffer(msg_ptr, msg_len)).decode('utf-8')
-    logger.log(level, msg)
-
   @_extern_decl('TypeId', ['ExternContext*', 'Handle*'])
   def extern_get_type_for(self, context_handle, val):
     """Return a representation of the object's type."""
@@ -628,7 +622,6 @@ def context(self):
     def init_externs():
       context = ExternContext(self.ffi, self.lib)
       self.lib.externs_set(context._handle,
-                           self.ffi_lib.extern_log,
                            logger.getEffectiveLevel(),
                            self.ffi_lib.extern_call,
                            self.ffi_lib.extern_generator_send,
@@ -679,6 +672,25 @@ def decompress_tarball(self, tarfile_path, dest_dir):
     result = self.lib.decompress_tarball(tarfile_path, dest_dir)
     return self.context.raise_or_return(result)
 
+  def init_rust_logging(self, level):
+    return self.lib.init_logging(level)
+
+  def setup_pantsd_logger(self, log_file_path, level):
+    log_file_path = log_file_path.encode("utf-8")
+    result = self.lib.setup_pantsd_logger(log_file_path, level)
+    return self.context.raise_or_return(result)
+
+  def setup_stderr_logger(self, level):
+    return self.lib.setup_stderr_logger(level)
+
+  def write_log(self, msg, level, target):
+    msg = msg.encode("utf-8")
+    target = target.encode("utf-8")
+    return self.lib.write_log(msg, level, target)
+
+  def flush_log(self):
+    return self.lib.flush_log()
+
   def match_path_globs(self, path_globs, paths):
     path_globs = self.context.to_value(path_globs)
     paths_buf = self.context.utf8_buf_buf(tuple(paths))

src/python/pants/init/BUILD

@@ -11,6 +11,7 @@ python_library(
     '3rdparty/python/twitter/commons:twitter.common.collections',
     'src/python/pants/backend/python/subsystems',
     'src/python/pants/base:build_environment',
+    'src/python/pants/base:exception_sink',
     'src/python/pants/base:exceptions',
     'src/python/pants/base:target_roots',
     'src/python/pants/binaries',

src/python/pants/init/logging.py

@@ -7,12 +7,13 @@
 import logging
 import os
 import sys
-import time
 from collections import namedtuple
-from logging import FileHandler, Formatter, StreamHandler
+from logging import StreamHandler
 
 from future.moves.http import client
 
+from pants.base.exception_sink import ExceptionSink
+from pants.engine.native import Native
 from pants.util.dirutil import safe_mkdir
 
 
@@ -42,13 +43,71 @@ def _maybe_configure_extended_logging(logger):
     _configure_requests_debug_logging()
 
 
+def init_rust_logger(level):
+  native = Native()
+  levelno = get_numeric_level(level)
+  native.init_rust_logging(levelno)
+
+
+def setup_logging_to_stderr(python_logger, level):
+  """
+  We setup logging as loose as possible from the Python side,
+  and let Rust do the filtering.
+  """
+  native = Native()
+  levelno = get_numeric_level(level)
+  handler = create_native_stderr_log_handler(levelno, native, stream=sys.stderr)
+  python_logger.addHandler(handler)
+  # Let the rust side filter levels; try to have the python side send everything to the rust logger.
+  python_logger.setLevel("TRACE")
+
+
 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()
-  return setup_logging(level, console_stream=sys.stderr, log_dir=bootstrap_options.logdir)
+  native = Native()
+  return setup_logging(level, console_stream=sys.stderr, log_dir=bootstrap_options.logdir, native=native)
+
+
+class NativeHandler(StreamHandler):
+
+  def __init__(self, level, native=None, stream=None, native_filename=None):
+    super(NativeHandler, self).__init__(stream)
+    self.native = native
+    self.native_filename = native_filename
+    self.setLevel(level)
+
+  def emit(self, record):
+    self.native.write_log(self.format(record), record.levelno, "{}:pid={}".format(record.name, os.getpid()))
+
+  def flush(self):
+    self.native.flush_log()
 
 
-def setup_logging(level, console_stream=None, log_dir=None, scope=None, log_name=None):
+def create_native_pantsd_file_log_handler(level, native, native_filename):
+  fd = native.setup_pantsd_logger(native_filename, get_numeric_level(level))
+  ExceptionSink.reset_interactive_output_stream(os.fdopen(os.dup(fd), 'a'))
+  return NativeHandler(level, native, native_filename=native_filename)
+
+
+def create_native_stderr_log_handler(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, stream)
+
+
+# TODO This function relies on logging._checkLevel, which is private.
+# There is currently no good way to convert string levels to numeric values,
+# but if there is ever one, it may be worth changing this.
+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):
   """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:
@@ -63,6 +122,7 @@ def setup_logging(level, console_stream=None, log_dir=None, scope=None, log_name
                     The '.' separator providing the scope hierarchy.  By default the root logger is
                     configured.
   :param str log_name: The base name of the log file (defaults to 'pants.log').
+  :param Native native: An instance of the Native FFI lib, to register rust logging.
   :returns: The full path to the main log file if file logging is configured or else `None`.
   :rtype: str
   """
@@ -88,43 +148,19 @@ def trace(self, message, *args, **kwargs):
   for handler in logger.handlers:
     logger.removeHandler(handler)
 
+
   if console_stream:
-    console_handler = StreamHandler(stream=console_stream)
-    console_handler.setFormatter(Formatter(fmt='%(levelname)s] %(message)s'))
-    console_handler.setLevel(level)
-    logger.addHandler(console_handler)
+    native_handler = create_native_stderr_log_handler(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')
-    file_handler = FileHandler(log_filename)
-
-    class GlogFormatter(Formatter):
-      LEVEL_MAP = {
-        logging.FATAL: 'F',
-        logging.ERROR: 'E',
-        logging.WARN: 'W',
-        logging.INFO: 'I',
-        logging.DEBUG: 'D',
-        TRACE: 'T'
-      }
-
-      def format(self, record):
-        datetime = time.strftime('%m%d %H:%M:%S', time.localtime(record.created))
-        micros = int((record.created - int(record.created)) * 1e6)
-        return '{levelchar}{datetime}.{micros:06d} {process} {filename}:{lineno}] {msg}'.format(
-          levelchar=self.LEVEL_MAP[record.levelno],
-          datetime=datetime,
-          micros=micros,
-          process=record.process,
-          filename=record.filename,
-          lineno=record.lineno,
-          msg=record.getMessage()
-        )
-
-    file_handler.setFormatter(GlogFormatter())
-    file_handler.setLevel(level)
-    logger.addHandler(file_handler)
+
+    native_handler = create_native_pantsd_file_log_handler(level, native, log_filename)
+    file_handler = native_handler
+    logger.addHandler(native_handler)
+
 
   logger.setLevel(level)
 

src/python/pants/pantsd/pants_daemon.py

@@ -20,7 +20,7 @@
 from pants.bin.daemon_pants_runner import DaemonPantsRunner
 from pants.engine.native import Native
 from pants.init.engine_initializer import EngineInitializer
-from pants.init.logging import setup_logging
+from pants.init.logging import init_rust_logger, setup_logging
 from pants.init.options_initializer import BuildConfigInitializer
 from pants.option.arg_splitter import GLOBAL_SCOPE
 from pants.option.options_bootstrapper import OptionsBootstrapper
@@ -306,7 +306,8 @@ 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)
+      init_rust_logger(self._log_level)
+      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
@@ -315,7 +316,7 @@ def _pantsd_logging(self):
       sys.stderr = _LoggerStream(logging.getLogger(), logging.WARN, result.log_handler)
 
       self._logger.debug('logging initialized')
-      yield result.log_handler.stream
+      yield (result.log_handler.stream, result.log_handler.native_filename)
 
   def _setup_services(self, pants_services):
     for service in pants_services.services:
@@ -369,22 +370,30 @@ def run_sync(self):
     """Synchronously run pantsd."""
     # Switch log output to the daemon's log stream from here forward.
     self._close_stdio()
-    with self._pantsd_logging() as log_stream:
+    with self._pantsd_logging() as (log_stream, log_filename):
+
       # Register an exiter using os._exit to ensure we only close stdio streams once.
       ExceptionSink.reset_exiter(Exiter(exiter=os._exit))
 
-      # We don't have any stdio streams to log to anymore, but we can get tracebacks of the pantsd
-      # process by tailing the pantsd log and sending it SIGUSR2.
-      ExceptionSink.reset_interactive_output_stream(log_stream)
+      # We don't have any stdio streams to log to anymore, so we log to a file.
+      # We don't override the faulthandler destination because the stream we get will proxy things
+      # via the rust logging code, and faulthandler needs to be writing directly to a real file
+      # descriptor. When pantsd logging was originally initialised, we already set up faulthandler
+      # to log to the correct file descriptor, so don't override it.
+      #
+      # We can get tracebacks of the pantsd process by tailing the pantsd log and sending it
+      # SIGUSR2.
+      ExceptionSink.reset_interactive_output_stream(
+        log_stream,
+        override_faulthandler_destination=False,
+      )
 
       # Reset the log location and the backtrace preference from the global bootstrap options.
       global_bootstrap_options = self._bootstrap_options.for_global_scope()
       ExceptionSink.reset_should_print_backtrace_to_terminal(
         global_bootstrap_options.print_exception_stacktrace)
       ExceptionSink.reset_log_location(global_bootstrap_options.pants_workdir)
 
-      self._logger.info('pantsd starting, log level is {}'.format(self._log_level))
-
       self._native.set_panic_handler()
 
       # Set the process name in ps output to 'pantsd' vs './pants compile src/etc:: -ldebug'.