[V2-UI] Move logging to Rust

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'.