upstream/certbot
1
0
Fork 0
mirror of https://github.com/certbot/certbot.git synced 2026-06-03 13:59:02 -04:00
Code Issues Projects Releases Packages Wiki Activity Actions 4

Fixes #4719 (#4737) (#4740)

Browse source 
* 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 93310fe67c)
This commit is contained in:
Brad Warren 2017-05-25 14:07:40 -07:00 committed by GitHub
parent c5d11d333f
commit fbd0325673
2 changed files with 120 additions and 34 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

97
certbot/log.py
View file

@ -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.
: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):
"""Close the handler and the temporary log file."""
self._close(delete=False)
def _close(self, delete):
"""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

57
certbot/tests/log_test.py
View file

@ -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 except_hook
return except_hook(*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 post_arg_parse_except_hook
return post_arg_parse_except_hook(*args, **kwargs)
def setUp(self):
self.error_msg = 'test error message'