create singleton ExceptionSink object to centralize logging of fatal …

…errors (#6533)

### Problem

See #6530. We want to make it simpler to understand where logging of fatal errors occurs and to consume those logs in a structured way.

### Solution

- First step in implementing #6530, a (process-)global singleton to manage where logs are kept (no logging is done yet).
- Add some very basic validation of input and very basic tests.

### Result

We now have an object that can be used to centralize the logging of fatal errors and enables the creation of a single point of failure (by which I mean, a single area of code which describes where this process's exceptions are logged and how to access and append to them), to be implemented in followup PRs.

src/python/pants/base/BUILD

@@ -69,6 +69,14 @@ python_library(
   ]
 )
 
+python_library(
+  name = 'exception_sink',
+  sources = ['exception_sink.py'],
+  dependencies = [
+    'src/python/pants/util:dirutil',
+  ],
+)
+
 python_library(
   name = 'exceptions',
   sources = ['exceptions.py'],
@@ -226,6 +234,6 @@ python_library(
   dependencies=[
     '3rdparty/python:future',
     '3rdparty/python:faulthandler',
-    'src/python/pants/util:dirutil'
+    ':exception_sink',
   ]
 )

src/python/pants/base/exception_sink.py

@@ -0,0 +1,88 @@
+# coding=utf-8
+# Copyright 2018 Pants project contributors (see CONTRIBUTORS.md).
+# Licensed under the Apache License, Version 2.0 (see LICENSE).
+
+from __future__ import absolute_import, division, print_function, unicode_literals
+
+import datetime
+import logging
+import os
+import sys
+from builtins import object
+
+from pants.util.dirutil import is_writable_dir, safe_open
+
+
+logger = logging.getLogger(__name__)
+
+
+class ExceptionSink(object):
+  """A mutable singleton object representing where exceptions should be logged to."""
+
+  _destination = os.getcwd()
+
+  def __new__(cls, *args, **kwargs):
+    raise TypeError('Instances of {} are not allowed to be constructed!'
+                    .format(cls.__name__))
+
+  class ExceptionSinkError(Exception): pass
+
+  @classmethod
+  def set_destination(cls, dir_path):
+    if not is_writable_dir(dir_path):
+      # TODO: when this class sets up excepthooks, raising this should be safe, because we always
+      # have a destination to log to (os.getcwd() if not otherwise set).
+      raise cls.ExceptionSinkError(
+        "The provided exception sink path at '{}' is not a writable directory."
+        .format(dir_path))
+    cls._destination = dir_path
+
+  @classmethod
+  def get_destination(cls):
+    return cls._destination
+
+  @classmethod
+  def _exceptions_log_path(cls, for_pid=None):
+    intermediate_filename_component = '.{}'.format(for_pid) if for_pid else ''
+    return os.path.join(
+      cls.get_destination(),
+      'logs',
+      'exceptions{}.log'.format(intermediate_filename_component))
+
+  @classmethod
+  def _iso_timestamp_for_now(cls):
+    return datetime.datetime.now().isoformat()
+
+  # NB: This includes a trailing newline, but no leading newline.
+  _EXCEPTION_LOG_FORMAT = """\
+timestamp: {timestamp}
+args: {args}
+pid: {pid}
+{message}
+"""
+
+  @classmethod
+  def _format_exception_message(cls, msg, pid):
+    return cls._EXCEPTION_LOG_FORMAT.format(
+      timestamp=cls._iso_timestamp_for_now(),
+      args=sys.argv,
+      pid=pid,
+      message=msg,
+    )
+
+  @classmethod
+  def log_exception(cls, msg):
+    try:
+      pid = os.getpid()
+      fatal_error_log_entry = cls._format_exception_message(msg, pid)
+      # We care more about this log than the shared log, so completely write to it first. This
+      # avoids any errors with concurrent modification of the shared log affecting the per-pid log.
+      with safe_open(cls._exceptions_log_path(for_pid=pid), 'a') as pid_error_log:
+        pid_error_log.write(fatal_error_log_entry)
+      # TODO: we should probably guard this against concurrent modification somehow.
+      with safe_open(cls._exceptions_log_path(), 'a') as shared_error_log:
+        shared_error_log.write(fatal_error_log_entry)
+    except Exception as e:
+      # TODO: If there is an error in writing to the exceptions log, we may want to consider trying
+      # to write to another location (e.g. the cwd, if that is not already the destination).
+      logger.error('Problem logging original exception: {}'.format(e))

src/python/pants/base/exiter.py

@@ -4,18 +4,16 @@
 
 from __future__ import absolute_import, division, print_function, unicode_literals
 
-import datetime
 import faulthandler
 import logging
-import os
 import signal
 import sys
 import traceback
 from builtins import object, str
 
 from future.utils import PY2
 
-from pants.util.dirutil import safe_open
+from pants.base.exception_sink import ExceptionSink
 
 
 logger = logging.getLogger(__name__)
@@ -103,18 +101,8 @@ def format_msg(print_backtrace=True):
 
   def _log_exception(self, msg):
     if self._workdir:
-      try:
-        output_path = os.path.join(self._workdir, 'logs', 'exceptions.log')
-        with safe_open(output_path, 'a') as exception_log:
-          exception_log.write('timestamp: {}\n'.format(datetime.datetime.now().isoformat()))
-          exception_log.write('args: {}\n'.format(sys.argv))
-          exception_log.write('pid: {}\n'.format(os.getpid()))
-          exception_log.write(msg)
-          exception_log.write('\n')
-      except Exception as e:
-        # This is all error recovery logic so we catch all exceptions from the logic above because
-        # we don't want to hide the original error.
-        logger.error('Problem logging original exception: {}'.format(e))
+      ExceptionSink.set_destination(self._workdir)
+    ExceptionSink.log_exception(msg)
 
   def _setup_faulthandler(self, trace_stream):
     faulthandler.enable(trace_stream)

src/python/pants/util/dirutil.py

@@ -535,5 +535,13 @@ def check_no_overlapping_paths(paths):
 
 
 def is_readable_dir(path):
-  """Returns whether a path names an existing directory that we can read."""
-  return os.path.isdir(path) and os.access(path, os.R_OK)
+  """Returns whether a path names an existing directory we can list and read files from."""
+  return os.path.isdir(path) and os.access(path, os.R_OK) and os.access(path, os.X_OK)
+
+
+def is_writable_dir(path):
+  """Returns whether a path names an existing directory that we can create and modify files in.
+
+  We call is_readable_dir(), so this definition of "writable" is a superset of that.
+  """
+  return is_readable_dir(path) and os.access(path, os.W_OK)

tests/python/pants_test/base/BUILD

@@ -205,6 +205,19 @@ python_tests(
   ]
 )
 
+python_tests(
+  name = 'exception_sink',
+  sources = ['test_exception_sink.py'],
+  dependencies = [
+    '3rdparty/python:future',
+    'src/python/pants/base:exception_sink',
+    'src/python/pants/util:collections',
+    'src/python/pants/util:contextutil',
+    'src/python/pants/util:dirutil',
+    'tests/python/pants_test:test_base',
+  ],
+)
+
 python_tests(
   name = 'exiter',
   sources = ['test_exiter.py'],

tests/python/pants_test/base/test_exception_sink.py

@@ -0,0 +1,87 @@
+# coding=utf-8
+# Copyright 2018 Pants project contributors (see CONTRIBUTORS.md).
+# Licensed under the Apache License, Version 2.0 (see LICENSE).
+
+from __future__ import absolute_import, division, print_function, unicode_literals
+
+import logging
+import os
+import re
+from builtins import open, str
+
+from pants.base.exception_sink import ExceptionSink
+from pants.util.collections import assert_single_element
+from pants.util.contextutil import temporary_dir
+from pants.util.dirutil import touch
+from pants_test.test_base import TestBase
+
+
+class TestExceptionSink(TestBase):
+
+  def _gen_sink_subclass(self):
+    # Avoid modifying global state by generating a subclass.
+    class AnonymousSink(ExceptionSink): pass
+    return AnonymousSink
+
+  def test_unset_destination(self):
+    self.assertEqual(os.getcwd(), self._gen_sink_subclass().get_destination())
+
+  def test_set_invalid_destination(self):
+    sink = self._gen_sink_subclass()
+    err_rx = re.escape(
+      "The provided exception sink path at '/does/not/exist' is not a writable directory.")
+    with self.assertRaisesRegexp(ExceptionSink.ExceptionSinkError, err_rx):
+      sink.set_destination('/does/not/exist')
+    err_rx = re.escape(
+      "The provided exception sink path at '/' is not a writable directory.")
+    with self.assertRaisesRegexp(ExceptionSink.ExceptionSinkError, err_rx):
+      sink.set_destination('/')
+
+  def test_retrieve_destination(self):
+    sink = self._gen_sink_subclass()
+
+    with temporary_dir() as tmpdir:
+      sink.set_destination(tmpdir)
+      self.assertEqual(tmpdir, sink.get_destination())
+
+  def test_log_exception(self):
+    sink = self._gen_sink_subclass()
+    pid = os.getpid()
+    with temporary_dir() as tmpdir:
+      # Check that tmpdir exists, and log an exception into that directory.
+      sink.set_destination(tmpdir)
+      sink.log_exception('XXX')
+      # This should have created two log files, one specific to the current pid.
+      self.assertEqual(os.listdir(tmpdir), ['logs'])
+      cur_process_error_log_path = os.path.join(tmpdir, 'logs', 'exceptions.{}.log'.format(pid))
+      self.assertTrue(os.path.isfile(cur_process_error_log_path))
+      shared_error_log_path = os.path.join(tmpdir, 'logs', 'exceptions.log')
+      self.assertTrue(os.path.isfile(shared_error_log_path))
+      # We only logged a single error, so the files should both contain only that single log entry.
+      err_rx = """\
+timestamp: ([^\n]+)
+args: ([^\n]+)
+pid: {pid}
+XXX
+""".format(pid=re.escape(str(pid)))
+      with open(cur_process_error_log_path, 'r') as cur_pid_file:
+        self.assertRegexpMatches(cur_pid_file.read(), err_rx)
+      with open(shared_error_log_path, 'r') as shared_log_file:
+        self.assertRegexpMatches(shared_log_file.read(), err_rx)
+
+  def test_backup_logging_on_fatal_error(self):
+    sink = self._gen_sink_subclass()
+    with self.captured_logging(level=logging.ERROR) as captured:
+      with temporary_dir() as tmpdir:
+        exc_log_path = os.path.join(tmpdir, 'logs', 'exceptions.log')
+        touch(exc_log_path)
+        # Make the exception log file unreadable.
+        os.chmod(exc_log_path, 0)
+        sink.set_destination(tmpdir)
+        sink.log_exception('XXX')
+    single_error_logged = str(assert_single_element(captured.errors()))
+    expected_rx_str = (
+      re.escape("pants.base.exception_sink: Problem logging original exception: [Errno 13] Permission denied: '") +
+      '.*' +
+      re.escape("/logs/exceptions.log'"))
+    self.assertRegexpMatches(single_error_logged, expected_rx_str)

tests/python/pants_test/test_base.py

@@ -616,6 +616,9 @@ def infos(self):
     def warnings(self):
       return self._messages_for_level('WARNING')
 
+    def errors(self):
+      return self._messages_for_level('ERROR')
+
   @contextmanager
   def captured_logging(self, level=None):
     root_logger = logging.getLogger()