diff options
| -rw-r--r-- | certbot/log.py | 97 | ||||
| -rw-r--r-- | certbot/tests/log_test.py | 57 |
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' |