Fixes #4719 (#4737) (#4740)

* Automatically delete temp log file when not used.

This allows close() calls in logging.shutdown() to cause the file to be
deleted when no logging output has been written to the file.

* Make certbot.log.MemoryHandler.flush() a noop.

This causes MemoryHandler.flush() calls in logging.shutdown to be a noop,
allowing us to control when the handler is actually flushed. This prevents log
records from being sent to a temporary file handler for things like
`certbot --version`.

* Keep reference to certbot.log.MemoryHandler.target

In Python 2.7+, the logging module only keeps weak references to created
logging handlers. Because of this, the MemoryHandler's target will not be
properly flushed and closed when logging.shutdown() is called on program exit
unless we keep a reference to it in the MemoryHandler.

* Fixes #4719.

This completes the changes necessary to fix #4719. Now temporary log files are
not created if sys.exit() is called before logging is fully set up. These files
are still created if Certbot crashes for any other reason.

* Document pre_arg_parse_except_hook args.

(cherry picked from commit 93310fe67c2f854593f5acb8bf74c914d6d81743)

2 files changed, 120 insertions, 34 deletions

diff --git a/certbot/log.py b/certbot/log.py
index c7bc867f1..889b5c50a 100644
--- a/certbot/log.py
+++ b/certbot/log.py
@@ -70,7 +70,8 @@ def pre_arg_parse_setup():
     # close() are explicitly called
     util.atexit_register(logging.shutdown)
     sys.excepthook = functools.partial(
-        except_hook, debug='--debug' in sys.argv, log_path=temp_handler.path)
+        pre_arg_parse_except_hook, memory_handler,
+        debug='--debug' in sys.argv, log_path=temp_handler.path)
 
 
 def post_arg_parse_setup(config):
@@ -103,8 +104,9 @@ def post_arg_parse_setup(config):
     root_logger.removeHandler(memory_handler)
     temp_handler = memory_handler.target
     memory_handler.setTarget(file_handler)
+    memory_handler.flush(force=True)
     memory_handler.close()
-    temp_handler.delete_and_close()
+    temp_handler.close()
 
     if config.quiet:
         level = constants.QUIET_LOGGING_LEVEL
@@ -115,7 +117,7 @@ def post_arg_parse_setup(config):
     logger.info('Saving debug log to %s', file_path)
 
     sys.excepthook = functools.partial(
-        except_hook, debug=config.debug, log_path=logs_dir)
+        post_arg_parse_except_hook, debug=config.debug, log_path=logs_dir)
 
 
 def setup_log_file_handler(config, logfile, fmt):
@@ -194,8 +196,7 @@ class MemoryHandler(logging.handlers.MemoryHandler):
     """Buffers logging messages in memory until the buffer is flushed.
 
     This differs from `logging.handlers.MemoryHandler` in that flushing
-    only happens when it is done explicitly by calling flush() or
-    close().
+    only happens when flush(force=True) is called.
 
     """
     def __init__(self, target=None):
@@ -209,6 +210,33 @@ class MemoryHandler(logging.handlers.MemoryHandler):
         else:
             super(MemoryHandler, self).__init__(capacity, target=target)
 
+    def close(self):
+        """Close the memory handler, but don't set the target to None."""
+        # This allows the logging module which may only have a weak
+        # reference to the target handler to properly flush and close it.
+        target = self.target
+        if sys.version_info < (2, 7):  # pragma: no cover
+            logging.handlers.MemoryHandler.close(self)
+        else:
+            super(MemoryHandler, self).close()
+        self.target = target
+
+    def flush(self, force=False):  # pylint: disable=arguments-differ
+        """Flush the buffer if force=True.
+
+        If force=False, this call is a noop.
+
+        :param bool force: True if the buffer should be flushed.
+
+        """
+        # This method allows flush() calls in logging.shutdown to be a
+        # noop so we can control when this handler is flushed.
+        if force:
+            if sys.version_info < (2, 7):  # pragma: no cover
+                logging.handlers.MemoryHandler.flush(self)
+            else:
+                super(MemoryHandler, self).flush()
+
     def shouldFlush(self, record):
         """Should the buffer be automatically flushed?
 
@@ -224,7 +252,9 @@ class MemoryHandler(logging.handlers.MemoryHandler):
 class TempHandler(logging.StreamHandler):
     """Safely logs messages to a temporary file.
 
-    The file is created with permissions 600.
+    The file is created with permissions 600. If no log records are sent
+    to this handler, the temporary file is deleted when the handler is
+    closed.
 
     :ivar str path: file system path to the temporary log file
 
@@ -238,19 +268,26 @@ class TempHandler(logging.StreamHandler):
         else:
             super(TempHandler, self).__init__(stream)
         self.path = stream.name
+        self._delete = True
 
-    def delete_and_close(self):
-        """Close the handler and delete the temporary log file."""
-        self._close(delete=True)
+    def emit(self, record):
+        """Log the specified logging record.
 
-    def close(self):
-        """Close the handler and the temporary log file."""
-        self._close(delete=False)
+        :param logging.LogRecord record: Record to be formatted
+
+        """
+        self._delete = False
+        # logging handlers use old style classes in Python 2.6 so
+        # super() cannot be used
+        if sys.version_info < (2, 7):  # pragma: no cover
+            logging.StreamHandler.emit(self, record)
+        else:
+            super(TempHandler, self).emit(record)
 
-    def _close(self, delete):
+    def close(self):
         """Close the handler and the temporary log file.
 
-        :param bool delete: True if the log file should be deleted
+        The temporary log file is deleted if it wasn't used.
 
         """
         self.acquire()
@@ -258,8 +295,9 @@ class TempHandler(logging.StreamHandler):
             # StreamHandler.close() doesn't close the stream to allow a
             # stream like stderr to be used
             self.stream.close()
-            if delete:
+            if self._delete:
                 os.remove(self.path)
+            self._delete = False
             if sys.version_info < (2, 7):  # pragma: no cover
                 logging.StreamHandler.close(self)
             else:
@@ -268,7 +306,34 @@ class TempHandler(logging.StreamHandler):
             self.release()
 
 
-def except_hook(exc_type, exc_value, trace, debug, log_path):
+def pre_arg_parse_except_hook(memory_handler, *args, **kwargs):
+    """A simple wrapper around post_arg_parse_except_hook.
+
+    The additional functionality provided by this wrapper is the memory
+    handler will be flushed before Certbot exits. This allows us to
+    write logging messages to a temporary file if we crashed before
+    logging was fully configured.
+
+    Since sys.excepthook isn't called on SystemExit exceptions, the
+    memory handler will not be flushed in this case which prevents us
+    from creating temporary log files when argparse exits because a
+    command line argument was invalid or -h, --help, or --version was
+    provided on the command line.
+
+    :param MemoryHandler memory_handler: memory handler to flush
+    :param tuple args: args for post_arg_parse_except_hook
+    :param dict kwargs: kwargs for post_arg_parse_except_hook
+
+    """
+    try:
+        post_arg_parse_except_hook(*args, **kwargs)
+    finally:
+        # flush() is called here so messages logged during
+        # post_arg_parse_except_hook are also flushed.
+        memory_handler.flush(force=True)
+
+
+def post_arg_parse_except_hook(exc_type, exc_value, trace, debug, log_path):
     """Logs fatal exceptions and reports them to the user.
 
     If debug is True, the full exception and traceback is shown to the
diff --git a/certbot/tests/log_test.py b/certbot/tests/log_test.py
index 13021220b..72ff076dd 100644
--- a/certbot/tests/log_test.py
+++ b/certbot/tests/log_test.py
@@ -26,7 +26,7 @@ class PreArgParseSetupTest(unittest.TestCase):
         return pre_arg_parse_setup(*args, **kwargs)
 
     @mock.patch('certbot.log.sys')
-    @mock.patch('certbot.log.except_hook')
+    @mock.patch('certbot.log.pre_arg_parse_except_hook')
     @mock.patch('certbot.log.logging.getLogger')
     @mock.patch('certbot.log.util.atexit_register')
     def test_it(self, mock_register, mock_get, mock_except_hook, mock_sys):
@@ -34,11 +34,6 @@ class PreArgParseSetupTest(unittest.TestCase):
         mock_sys.version_info = sys.version_info
         self._call()
 
-        mock_register.assert_called_once_with(logging.shutdown)
-        mock_sys.excepthook(1, 2, 3)
-        mock_except_hook.assert_called_once_with(
-            1, 2, 3, debug=True, log_path=mock.ANY)
-
         mock_root_logger = mock_get()
         mock_root_logger.setLevel.assert_called_once_with(logging.DEBUG)
         self.assertEqual(mock_root_logger.addHandler.call_count, 2)
@@ -54,6 +49,11 @@ class PreArgParseSetupTest(unittest.TestCase):
         self.assertTrue(
             isinstance(memory_handler.target, logging.StreamHandler))
 
+        mock_register.assert_called_once_with(logging.shutdown)
+        mock_sys.excepthook(1, 2, 3)
+        mock_except_hook.assert_called_once_with(
+            memory_handler, 1, 2, 3, debug=True, log_path=mock.ANY)
+
 
 class PostArgParseSetupTest(test_util.TempDirTestCase):
     """Tests for certbot.log.post_arg_parse_setup."""
@@ -88,7 +88,8 @@ class PostArgParseSetupTest(test_util.TempDirTestCase):
     def test_common(self):
         with mock.patch('certbot.log.logging.getLogger') as mock_get_logger:
             mock_get_logger.return_value = self.root_logger
-            with mock.patch('certbot.log.except_hook') as mock_except_hook:
+            except_hook_path = 'certbot.log.post_arg_parse_except_hook'
+            with mock.patch(except_hook_path) as mock_except_hook:
                 with mock.patch('certbot.log.sys') as mock_sys:
                     mock_sys.version_info = sys.version_info
                     self._call(self.config)
@@ -203,12 +204,13 @@ class MemoryHandlerTest(unittest.TestCase):
 
     def test_flush(self):
         self._test_log_debug()
-        self.handler.flush()
+        self.handler.flush(force=True)
         self.assertEqual(self.stream.getvalue(), self.msg + '\n')
 
     def test_not_flushed(self):
         # By default, logging.ERROR messages and higher are flushed
         self.logger.critical(self.msg)
+        self.handler.flush()
         self.assertEqual(self.stream.getvalue(), '')
 
     def test_target_reset(self):
@@ -217,7 +219,7 @@ class MemoryHandlerTest(unittest.TestCase):
         new_stream = six.StringIO()
         new_stream_handler = logging.StreamHandler(new_stream)
         self.handler.setTarget(new_stream_handler)
-        self.handler.flush()
+        self.handler.flush(force=True)
         self.assertEqual(self.stream.getvalue(), '')
         self.assertEqual(new_stream.getvalue(), self.msg + '\n')
         new_stream_handler.close()
@@ -234,31 +236,50 @@ class TempHandlerTest(unittest.TestCase):
         self.handler = TempHandler()
 
     def tearDown(self):
-        if not self.closed:
-            self.handler.delete_and_close()
+        self.handler.close()
 
     def test_permissions(self):
         self.assertTrue(
             util.check_permissions(self.handler.path, 0o600, os.getuid()))
 
     def test_delete(self):
-        self.handler.delete_and_close()
-        self.closed = True
+        self.handler.close()
         self.assertFalse(os.path.exists(self.handler.path))
 
     def test_no_delete(self):
+        self.handler.emit(mock.MagicMock())
         self.handler.close()
-        self.closed = True
         self.assertTrue(os.path.exists(self.handler.path))
         os.remove(self.handler.path)
 
 
-class ExceptHookTest(unittest.TestCase):
-    """Tests for certbot.log.except_hook."""
+class PreArgParseExceptHookTest(unittest.TestCase):
+    """Tests for certbot.log.pre_arg_parse_except_hook."""
+    @classmethod
+    def _call(cls, *args, **kwargs):
+        from certbot.log import pre_arg_parse_except_hook
+        return pre_arg_parse_except_hook(*args, **kwargs)
+
+    @mock.patch('certbot.log.post_arg_parse_except_hook')
+    def test_it(self, mock_post_arg_parse_except_hook):
+        # pylint: disable=star-args
+        memory_handler = mock.MagicMock()
+        args = ('some', 'args',)
+        kwargs = {'some': 'kwargs'}
+
+        self._call(memory_handler, *args, **kwargs)
+
+        mock_post_arg_parse_except_hook.assert_called_once_with(
+            *args, **kwargs)
+        memory_handler.flush.assert_called_once_with(force=True)
+
+
+class PostArgParseExceptHookTest(unittest.TestCase):
+    """Tests for certbot.log.post_arg_parse_except_hook."""
     @classmethod
     def _call(cls, *args, **kwargs):
-        from certbot.log import except_hook
-        return except_hook(*args, **kwargs)
+        from certbot.log import post_arg_parse_except_hook
+        return post_arg_parse_except_hook(*args, **kwargs)
 
     def setUp(self):
         self.error_msg = 'test error message'