Files
certbot-certbot-2/certbot/tests/util.py
T
Adrien FerrandandBrad Warren b10ceb7d90 Fix test sdists with atexit handlers (#6769)
So merging the study from @bmw and me, here is what happened.

Each invocation of `certbot.logger.post_arg_parse_setup` create a file handler on `letsencrypt.log`. This function also set an atexit handler invoking `logger.shutdown()`, that have the effect to close all logger file handler not already closed at this point. This method is supposed to be called when a python process is close to exit, because it makes all logger unable to write new logs on any handler.

Before #6667 and this PR, for tests, the atexit handle would be triggered only at the end of the pytest process. It means that each test that launches `certbot.logger.post_arg_parse_setup` add a new file handler. These tests were typically connecting the file handler on a `letsencrypt.log` located in a temporary directory, and this directory and content was wipped out at each test tearDown. As a consequence, the file handles, not cleared from the logger, were accumulating in the logger, with all of them connected to a deleted file log, except the last one that was just created by the current test. Considering the number of tests concerned, there were ~300 file handler at the end of pytest execution.

One can see that, on prior #6667, by calling `print(logger.getLogger().handlers` on the `tearDown` of these tests, and see the array growing at each test execution.

Even if this represent a memory leak, this situation was not really a problem on Linux: because a file can be deleted before it is closed, it was only meaning that a given invocation of `logger.debug` for instance, during the tests, was written in 300 log files. The overhead is negligeable. On Windows however, the file handlers were failing because you cannot delete a file before it is closed.

It was one of the reason for #6667, that added a call to `logging.shutdown()` at each test tearDown, with the consequence to close all file handlers. At this point, Linux is not happy anymore. Any call to `logger.warn` will generate an error for each closed file handler. As a file handler is added for each test, the number of errors grows on each test, following an arithmetical suite divergence.

On `test_sdists.py`, that is using the bare setuptools test suite without output capturing, we can see the damages. The total output takes 216000 lines, and 23000 errors are generated. A decent machine can support this load, but a not a small AWS instance, that is crashing during the execution. Even with pytest, the captured output and the memory leak become so large that segfaults are generated.

On the current PR, the problem is solved, by resetting the file handlers array on the logging system on each test tearDown. So each fileHandler is properly closed, and removed from the stack. They do not participate anymore in the logging system, and can be garbage collected. Then we stay on always one file handler opened at any time, and tests can succeed on AWS instances.

For the record, here is all the places where the logging system is called and fail if there is still file handlers closed but not cleaned (extracted from the original huge output before correction):

```
Logged from file account.py, line 116
Logged from file account.py, line 178
Logged from file client.py, line 166
Logged from file client.py, line 295
Logged from file client.py, line 415
Logged from file client.py, line 422
Logged from file client.py, line 480
Logged from file client.py, line 503
Logged from file client.py, line 540
Logged from file client.py, line 601
Logged from file client.py, line 622
Logged from file client.py, line 750
Logged from file cli.py, line 220
Logged from file cli.py, line 226
Logged from file crypto_util.py, line 101
Logged from file crypto_util.py, line 127
Logged from file crypto_util.py, line 147
Logged from file crypto_util.py, line 261
Logged from file crypto_util.py, line 283
Logged from file crypto_util.py, line 307
Logged from file crypto_util.py, line 336
Logged from file disco.py, line 116
Logged from file disco.py, line 124
Logged from file disco.py, line 134
Logged from file disco.py, line 138
Logged from file disco.py, line 141
Logged from file dns_common_lexicon.py, line 45
Logged from file dns_common_lexicon.py, line 61
Logged from file dns_common_lexicon.py, line 67
Logged from file dns_common.py, line 316
Logged from file dns_common.py, line 64
Logged from file eff.py, line 60
Logged from file eff.py, line 73
Logged from file error_handler.py, line 105
Logged from file error_handler.py, line 110
Logged from file error_handler.py, line 87
Logged from file hooks.py, line 248
Logged from file main.py, line 1071
Logged from file main.py, line 1075
Logged from file main.py, line 1189
Logged from file ops.py, line 122
Logged from file ops.py, line 325
Logged from file ops.py, line 338
Logged from file reporter.py, line 55
Logged from file selection.py, line 110
Logged from file selection.py, line 118
Logged from file selection.py, line 123
Logged from file selection.py, line 176
Logged from file selection.py, line 231
Logged from file selection.py, line 310
Logged from file selection.py, line 66
Logged from file standalone.py, line 101
Logged from file standalone.py, line 88
Logged from file standalone.py, line 97
Logged from file standalone.py, line 98
Logged from file storage.py, line 52
Logged from file storage.py, line 59
Logged from file storage.py, line 75
Logged from file util.py, line 56
Logged from file webroot.py, line 165
Logged from file webroot.py, line 186
Logged from file webroot.py, line 187
Logged from file webroot.py, line 204
Logged from file webroot.py, line 223
Logged from file webroot.py, line 234
Logged from file webroot.py, line 235
Logged from file webroot.py, line 237
Logged from file webroot.py, line 91
```

* Reapply #6667

* Make setuptools delegates tests execution to pytest, like in acme module.

* Clean handlers at each tearDown to avoid memory leaks.

* Update changelog
2019-02-21 16:55:08 -08:00

435 lines
15 KiB
Python

"""Test utilities.
.. warning:: This module is not part of the public API.
"""
import logging
import os
import pkg_resources
import shutil
import stat
import tempfile
import unittest
import sys
from multiprocessing import Process, Event
from cryptography.hazmat.backends import default_backend
from cryptography.hazmat.primitives import serialization
import mock
import OpenSSL
import josepy as jose
import six
from six.moves import reload_module # pylint: disable=import-error
from certbot import constants
from certbot import interfaces
from certbot import storage
from certbot import configuration
from certbot import lock
from certbot import util
from certbot.display import util as display_util
def vector_path(*names):
"""Path to a test vector."""
return pkg_resources.resource_filename(
__name__, os.path.join('testdata', *names))
def load_vector(*names):
"""Load contents of a test vector."""
# luckily, resource_string opens file in binary mode
data = pkg_resources.resource_string(
__name__, os.path.join('testdata', *names))
# Try at most to convert CRLF to LF when data is text
try:
return data.decode().replace('\r\n', '\n').encode()
except ValueError:
# Failed to process the file with standard encoding.
# Most likely not a text file, return its bytes untouched.
return data
def _guess_loader(filename, loader_pem, loader_der):
_, ext = os.path.splitext(filename)
if ext.lower() == '.pem':
return loader_pem
elif ext.lower() == '.der':
return loader_der
else: # pragma: no cover
raise ValueError("Loader could not be recognized based on extension")
def load_cert(*names):
"""Load certificate."""
loader = _guess_loader(
names[-1], OpenSSL.crypto.FILETYPE_PEM, OpenSSL.crypto.FILETYPE_ASN1)
return OpenSSL.crypto.load_certificate(loader, load_vector(*names))
def load_csr(*names):
"""Load certificate request."""
loader = _guess_loader(
names[-1], OpenSSL.crypto.FILETYPE_PEM, OpenSSL.crypto.FILETYPE_ASN1)
return OpenSSL.crypto.load_certificate_request(loader, load_vector(*names))
def load_comparable_csr(*names):
"""Load ComparableX509 certificate request."""
return jose.ComparableX509(load_csr(*names))
def load_rsa_private_key(*names):
"""Load RSA private key."""
loader = _guess_loader(names[-1], serialization.load_pem_private_key,
serialization.load_der_private_key)
return jose.ComparableRSAKey(loader(
load_vector(*names), password=None, backend=default_backend()))
def load_pyopenssl_private_key(*names):
"""Load pyOpenSSL private key."""
loader = _guess_loader(
names[-1], OpenSSL.crypto.FILETYPE_PEM, OpenSSL.crypto.FILETYPE_ASN1)
return OpenSSL.crypto.load_privatekey(loader, load_vector(*names))
def skip_unless(condition, reason): # pragma: no cover
"""Skip tests unless a condition holds.
This implements the basic functionality of unittest.skipUnless
which is only available on Python 2.7+.
:param bool condition: If ``False``, the test will be skipped
:param str reason: the reason for skipping the test
:rtype: callable
:returns: decorator that hides tests unless condition is ``True``
"""
if hasattr(unittest, "skipUnless"):
return unittest.skipUnless(condition, reason)
elif condition:
return lambda cls: cls
else:
return lambda cls: None
def make_lineage(config_dir, testfile):
"""Creates a lineage defined by testfile.
This creates the archive, live, and renewal directories if
necessary and creates a simple lineage.
:param str config_dir: path to the configuration directory
:param str testfile: configuration file to base the lineage on
:returns: path to the renewal conf file for the created lineage
:rtype: str
"""
lineage_name = testfile[:-len('.conf')]
conf_dir = os.path.join(
config_dir, constants.RENEWAL_CONFIGS_DIR)
archive_dir = os.path.join(
config_dir, constants.ARCHIVE_DIR, lineage_name)
live_dir = os.path.join(
config_dir, constants.LIVE_DIR, lineage_name)
for directory in (archive_dir, conf_dir, live_dir,):
if not os.path.exists(directory):
os.makedirs(directory)
sample_archive = vector_path('sample-archive')
for kind in os.listdir(sample_archive):
shutil.copyfile(os.path.join(sample_archive, kind),
os.path.join(archive_dir, kind))
for kind in storage.ALL_FOUR:
os.symlink(os.path.join(archive_dir, '{0}1.pem'.format(kind)),
os.path.join(live_dir, '{0}.pem'.format(kind)))
conf_path = os.path.join(config_dir, conf_dir, testfile)
with open(vector_path(testfile)) as src:
with open(conf_path, 'w') as dst:
dst.writelines(
line.replace('MAGICDIR', config_dir) for line in src)
return conf_path
def patch_get_utility(target='zope.component.getUtility'):
"""Patch zope.component.getUtility to use a special mock IDisplay.
The mock IDisplay works like a regular mock object, except it also
also asserts that methods are called with valid arguments.
:param str target: path to patch
:returns: mock zope.component.getUtility
:rtype: mock.MagicMock
"""
return mock.patch(target, new_callable=_create_get_utility_mock)
def patch_get_utility_with_stdout(target='zope.component.getUtility',
stdout=None):
"""Patch zope.component.getUtility to use a special mock IDisplay.
The mock IDisplay works like a regular mock object, except it also
also asserts that methods are called with valid arguments.
The `message` argument passed to the IDisplay methods is passed to
stdout's write method.
:param str target: path to patch
:param object stdout: object to write standard output to; it is
expected to have a `write` method
:returns: mock zope.component.getUtility
:rtype: mock.MagicMock
"""
stdout = stdout if stdout else six.StringIO()
freezable_mock = _create_get_utility_mock_with_stdout(stdout)
return mock.patch(target, new=freezable_mock)
class FreezableMock(object):
"""Mock object with the ability to freeze attributes.
This class works like a regular mock.MagicMock object, except
attributes and behavior set before the object is frozen cannot
be changed during tests.
If a func argument is provided to the constructor, this function
is called first when an instance of FreezableMock is called,
followed by the usual behavior defined by MagicMock. The return
value of func is ignored.
"""
def __init__(self, frozen=False, func=None, return_value=mock.sentinel.DEFAULT):
self._frozen_set = set() if frozen else {'freeze', }
self._func = func
self._mock = mock.MagicMock()
if return_value != mock.sentinel.DEFAULT:
self.return_value = return_value
self._frozen = frozen
def freeze(self):
"""Freeze object preventing further changes."""
self._frozen = True
def __call__(self, *args, **kwargs):
if self._func is not None:
self._func(*args, **kwargs)
return self._mock(*args, **kwargs)
def __getattribute__(self, name):
if name == '_frozen':
try:
return object.__getattribute__(self, name)
except AttributeError:
return False
elif name in ('return_value', 'side_effect',):
return getattr(object.__getattribute__(self, '_mock'), name)
elif name == '_frozen_set' or name in self._frozen_set:
return object.__getattribute__(self, name)
else:
return getattr(object.__getattribute__(self, '_mock'), name)
def __setattr__(self, name, value):
""" Before it is frozen, attributes are set on the FreezableMock
instance and added to the _frozen_set. Attributes in the _frozen_set
cannot be changed after the FreezableMock is frozen. In this case,
they are set on the underlying _mock.
In cases of return_value and side_effect, these attributes are always
passed through to the instance's _mock and added to the _frozen_set
before the object is frozen.
"""
if self._frozen:
if name in self._frozen_set:
raise AttributeError('Cannot change frozen attribute ' + name)
else:
return setattr(self._mock, name, value)
if name != '_frozen_set':
self._frozen_set.add(name)
if name in ('return_value', 'side_effect'):
return setattr(self._mock, name, value)
else:
return object.__setattr__(self, name, value)
def _create_get_utility_mock():
display = FreezableMock()
for name in interfaces.IDisplay.names(): # pylint: disable=no-member
if name != 'notification':
frozen_mock = FreezableMock(frozen=True, func=_assert_valid_call)
setattr(display, name, frozen_mock)
display.freeze()
return FreezableMock(frozen=True, return_value=display)
def _create_get_utility_mock_with_stdout(stdout):
def _write_msg(message, *unused_args, **unused_kwargs):
"""Write to message to stdout.
"""
if message:
stdout.write(message)
def mock_method(*args, **kwargs):
"""
Mock function for IDisplay methods.
"""
_assert_valid_call(args, kwargs)
_write_msg(*args, **kwargs)
display = FreezableMock()
for name in interfaces.IDisplay.names(): # pylint: disable=no-member
if name == 'notification':
frozen_mock = FreezableMock(frozen=True,
func=_write_msg)
setattr(display, name, frozen_mock)
else:
frozen_mock = FreezableMock(frozen=True,
func=mock_method)
setattr(display, name, frozen_mock)
display.freeze()
return FreezableMock(frozen=True, return_value=display)
def _assert_valid_call(*args, **kwargs):
assert_args = [args[0] if args else kwargs['message']]
assert_kwargs = {}
assert_kwargs['default'] = kwargs.get('default', None)
assert_kwargs['cli_flag'] = kwargs.get('cli_flag', None)
assert_kwargs['force_interactive'] = kwargs.get('force_interactive', False)
# pylint: disable=star-args
display_util.assert_valid_call(*assert_args, **assert_kwargs)
class TempDirTestCase(unittest.TestCase):
"""Base test class which sets up and tears down a temporary directory"""
def setUp(self):
"""Execute before test"""
self.tempdir = tempfile.mkdtemp()
def tearDown(self):
"""Execute after test"""
# Cleanup opened resources after a test. This is usually done through atexit handlers in
# Certbot, but during tests, atexit will not run registered functions before tearDown is
# called and instead will run them right before the entire test process exits.
# It is a problem on Windows, that does not accept to clean resources before closing them.
logging.shutdown()
# Remove logging handlers that have been closed so they won't be
# accidentally used in future tests.
logging.getLogger().handlers = []
util._release_locks() # pylint: disable=protected-access
def handle_rw_files(_, path, __):
"""Handle read-only files, that will fail to be removed on Windows."""
os.chmod(path, stat.S_IWRITE)
os.remove(path)
shutil.rmtree(self.tempdir, onerror=handle_rw_files)
class ConfigTestCase(TempDirTestCase):
"""Test class which sets up a NamespaceConfig object."""
def setUp(self):
super(ConfigTestCase, self).setUp()
self.config = configuration.NamespaceConfig(
mock.MagicMock(**constants.CLI_DEFAULTS)
)
self.config.verb = "certonly"
self.config.config_dir = os.path.join(self.tempdir, 'config')
self.config.work_dir = os.path.join(self.tempdir, 'work')
self.config.logs_dir = os.path.join(self.tempdir, 'logs')
self.config.cert_path = constants.CLI_DEFAULTS['auth_cert_path']
self.config.fullchain_path = constants.CLI_DEFAULTS['auth_chain_path']
self.config.chain_path = constants.CLI_DEFAULTS['auth_chain_path']
self.config.server = "https://example.com"
def _handle_lock(event_in, event_out, path):
"""
Acquire a file lock on given path, then wait to release it. This worker is coordinated
using events to signal when the lock should be acquired and released.
:param multiprocessing.Event event_in: event object to signal when to release the lock
:param multiprocessing.Event event_out: event object to signal when the lock is acquired
:param path: the path to lock
"""
if os.path.isdir(path):
my_lock = lock.lock_dir(path)
else:
my_lock = lock.LockFile(path)
try:
event_out.set()
assert event_in.wait(timeout=20), 'Timeout while waiting to release the lock.'
finally:
my_lock.release()
def lock_and_call(callback, path_to_lock):
"""
Grab a lock on path_to_lock from a foreign process then execute the callback.
:param callable callback: object to call after acquiring the lock
:param str path_to_lock: path to file or directory to lock
"""
# Reload certbot.util module to reset internal _LOCKS dictionary.
reload_module(util)
emit_event = Event()
receive_event = Event()
process = Process(target=_handle_lock, args=(emit_event, receive_event, path_to_lock))
process.start()
# Wait confirmation that lock is acquired
assert receive_event.wait(timeout=10), 'Timeout while waiting to acquire the lock.'
# Execute the callback
callback()
# Trigger unlock from foreign process
emit_event.set()
# Wait for process termination
process.join(timeout=10)
assert process.exitcode == 0
def skip_on_windows(reason):
"""Decorator to skip permanently a test on Windows. A reason is required."""
def wrapper(function):
"""Wrapped version"""
return unittest.skipIf(sys.platform == 'win32', reason)(function)
return wrapper
def broken_on_windows(function):
"""Decorator to skip temporarily a broken test on Windows."""
reason = 'Test is broken and ignored on windows but should be fixed.'
return unittest.skipIf(
sys.platform == 'win32'
and os.environ.get('SKIP_BROKEN_TESTS_ON_WINDOWS', 'true') == 'true',
reason)(function)
def temp_join(path):
"""
Return the given path joined to the tempdir path for the current platform
Eg.: 'cert' => /tmp/cert (Linux) or 'C:\\Users\\currentuser\\AppData\\Temp\\cert' (Windows)
"""
return os.path.join(tempfile.gettempdir(), path)