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

CHANGELOG.md

@@ -14,6 +14,7 @@ Certbot adheres to [Semantic Versioning](https://semver.org/).
   warnings described at https://github.com/certbot/josepy/issues/13.
 * Apache plugin now respects CERTBOT_DOCS environment variable when adding
   command line defaults.
+* Tests execution for certbot, certbot-apache and certbot-nginx packages now relies on pytest.
 
 ### Fixed
 
@@ -26,6 +27,7 @@ package with changes other than its version number was:
 * acme
 * certbot
 * certbot-apache
+* certbot-nginx
 
 More details about these changes can be found on our GitHub repo.
 

acme/setup.py

@@ -36,6 +36,7 @@ docs_extras = [
     'sphinx_rtd_theme',
 ]
 
+
 class PyTest(TestCommand):
     user_options = []
 
@@ -50,6 +51,7 @@ class PyTest(TestCommand):
         errno = pytest.main(shlex.split(self.pytest_args))
         sys.exit(errno)
 
+
 setup(
     name='acme',
     version=version,
@@ -82,7 +84,7 @@ setup(
         'dev': dev_extras,
         'docs': docs_extras,
     },
-    tests_require=["pytest"],
     test_suite='acme',
+    tests_require=["pytest"],
     cmdclass={"test": PyTest},
 )

certbot-apache/setup.py

@@ -1,5 +1,7 @@
 from setuptools import setup
 from setuptools import find_packages
+from setuptools.command.test import test as TestCommand
+import sys
 
 
 version = '0.32.0.dev0'
@@ -21,6 +23,22 @@ docs_extras = [
     'sphinx_rtd_theme',
 ]
 
+
+class PyTest(TestCommand):
+    user_options = []
+
+    def initialize_options(self):
+        TestCommand.initialize_options(self)
+        self.pytest_args = ''
+
+    def run_tests(self):
+        import shlex
+        # import here, cause outside the eggs aren't loaded
+        import pytest
+        errno = pytest.main(shlex.split(self.pytest_args))
+        sys.exit(errno)
+
+
 setup(
     name='certbot-apache',
     version=version,
@@ -64,4 +82,6 @@ setup(
         ],
     },
     test_suite='certbot_apache',
+    tests_require=["pytest"],
+    cmdclass={"test": PyTest},
 )

certbot-nginx/setup.py

@@ -1,5 +1,7 @@
 from setuptools import setup
 from setuptools import find_packages
+from setuptools.command.test import test as TestCommand
+import sys
 
 
 version = '0.32.0.dev0'
@@ -21,6 +23,22 @@ docs_extras = [
     'sphinx_rtd_theme',
 ]
 
+
+class PyTest(TestCommand):
+    user_options = []
+
+    def initialize_options(self):
+        TestCommand.initialize_options(self)
+        self.pytest_args = ''
+
+    def run_tests(self):
+        import shlex
+        # import here, cause outside the eggs aren't loaded
+        import pytest
+        errno = pytest.main(shlex.split(self.pytest_args))
+        sys.exit(errno)
+
+
 setup(
     name='certbot-nginx',
     version=version,
@@ -64,4 +82,6 @@ setup(
         ],
     },
     test_suite='certbot_nginx',
+    tests_require=["pytest"],
+    cmdclass={"test": PyTest},
 )

certbot/tests/lock_test.py

@@ -41,6 +41,7 @@ class LockFileTest(test_util.TempDirTestCase):
         super(LockFileTest, self).setUp()
         self.lock_path = os.path.join(self.tempdir, 'test.lock')
 
+    @test_util.broken_on_windows
     def test_acquire_without_deletion(self):
         # acquire the lock in another process but don't delete the file
         child = multiprocessing.Process(target=self._call,
@@ -58,6 +59,7 @@ class LockFileTest(test_util.TempDirTestCase):
             self.assertRaises, errors.LockError, self._call, self.lock_path)
         test_util.lock_and_call(assert_raises, self.lock_path)
 
+    @test_util.broken_on_windows
     def test_locked_repr(self):
         lock_file = self._call(self.lock_path)
         locked_repr = repr(lock_file)
@@ -92,6 +94,7 @@ class LockFileTest(test_util.TempDirTestCase):
             self._call(self.lock_path)
         self.assertFalse(should_delete)
 
+    @test_util.broken_on_windows
     def test_removed(self):
         lock_file = self._call(self.lock_path)
         lock_file.release()

certbot/tests/util.py

@@ -3,13 +3,14 @@
 .. 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
-import warnings
 from multiprocessing import Process, Event
 
 from cryptography.hazmat.backends import default_backend
@@ -329,23 +330,25 @@ class TempDirTestCase(unittest.TestCase):
 
     def tearDown(self):
         """Execute after test"""
-        # On Windows we have various files which are not correctly closed at the time of tearDown.
+        # Cleanup opened resources after a test. This is usually done through atexit handlers in
-        # For know, we log them until a proper file close handling is written.
+        # Certbot, but during tests, atexit will not run registered functions before tearDown is
-        # Useful for development only, so no warning when we are on a CI process.
+        # called and instead will run them right before the entire test process exits.
-        def onerror_handler(_, path, excinfo):
+        # It is a problem on Windows, that does not accept to clean resources before closing them.
-            """On error handler"""
+        logging.shutdown()
-            if not os.environ.get('APPVEYOR'): # pragma: no cover
+        # Remove logging handlers that have been closed so they won't be
-                message = ('Following error occurred when deleting the tempdir {0}'
+        # accidentally used in future tests.
-                           ' for path {1} during tearDown process: {2}'
+        logging.getLogger().handlers = []
-                           .format(self.tempdir, path, str(excinfo)))
+        util._release_locks()  # pylint: disable=protected-access
-                warnings.warn(message)
+
-        shutil.rmtree(self.tempdir, onerror=onerror_handler)
+        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.
+    """Test class which sets up a NamespaceConfig object."""
-
-    """
     def setUp(self):
         super(ConfigTestCase, self).setUp()
         self.config = configuration.NamespaceConfig(

certbot/tests/util_test.py

@@ -193,7 +193,12 @@ class CheckPermissionsTest(test_util.TempDirTestCase):
 
     def test_wrong_mode(self):
         os.chmod(self.tempdir, 0o400)
-        self.assertFalse(self._call(0o600))
+        try:
+            self.assertFalse(self._call(0o600))
+        finally:
+            # Without proper write permissions, Windows is unable to delete a folder,
+            # even with admin permissions. Write access must be explicitly set first.
+            os.chmod(self.tempdir, 0o700)
 
 
 class UniqueFileTest(test_util.TempDirTestCase):
@@ -279,20 +284,9 @@ class UniqueLineageNameTest(test_util.TempDirTestCase):
         for f, _ in items:
             f.close()
 
-    @mock.patch("certbot.util.os.fdopen")
+    def test_failure(self):
-    def test_failure(self, mock_fdopen):
+        with mock.patch("certbot.util.os.open", side_effect=OSError(errno.EIO)):
-        err = OSError("whoops")
+            self.assertRaises(OSError, self._call, "wow")
-        err.errno = errno.EIO
-        mock_fdopen.side_effect = err
-        self.assertRaises(OSError, self._call, "wow")
-
-    @mock.patch("certbot.util.os.fdopen")
-    def test_subsequent_failure(self, mock_fdopen):
-        self._call("wow")
-        err = OSError("whoops")
-        err.errno = errno.EIO
-        mock_fdopen.side_effect = err
-        self.assertRaises(OSError, self._call, "wow")
 
 
 class SafelyRemoveTest(test_util.TempDirTestCase):

certbot/util.py

@@ -142,6 +142,7 @@ def _release_locks():
         except:  # pylint: disable=bare-except
             msg = 'Exception occurred releasing lock: {0!r}'.format(dir_lock)
             logger.debug(msg, exc_info=True)
+    _LOCKS.clear()
 
 
 def set_up_core_dir(directory, mode, uid, strict):
@@ -225,9 +226,8 @@ def safe_open(path, mode="w", chmod=None, buffering=None):
     fdopen_args = ()  # type: Union[Tuple[()], Tuple[int]]
     if buffering is not None:
         fdopen_args = (buffering,)
-    return os.fdopen(
+    fd = os.open(path, os.O_CREAT | os.O_EXCL | os.O_RDWR, *open_args)
-        os.open(path, os.O_CREAT | os.O_EXCL | os.O_RDWR, *open_args),
+    return os.fdopen(fd, mode, *fdopen_args)
-        mode, *fdopen_args)
 
 
 def _unique_file(path, filename_pat, count, chmod, mode):

setup.py

@@ -1,8 +1,10 @@
 import codecs
 import os
 import re
+import sys
 
 from setuptools import find_packages, setup
+from setuptools.command.test import test as TestCommand
 
 # Workaround for http://bugs.python.org/issue8876, see
 # http://bugs.python.org/issue8876#msg208792
@@ -77,6 +79,22 @@ docs_extras = [
     'sphinx_rtd_theme',
 ]
 
+
+class PyTest(TestCommand):
+    user_options = []
+
+    def initialize_options(self):
+        TestCommand.initialize_options(self)
+        self.pytest_args = ''
+
+    def run_tests(self):
+        import shlex
+        # import here, cause outside the eggs aren't loaded
+        import pytest
+        errno = pytest.main(shlex.split(self.pytest_args))
+        sys.exit(errno)
+
+
 setup(
     name='certbot',
     version=version,
@@ -123,6 +141,8 @@ setup(
     # to test all packages run "python setup.py test -s
     # {acme,certbot_apache,certbot_nginx}"
     test_suite='certbot',
+    tests_require=["pytest"],
+    cmdclass={"test": PyTest},
 
     entry_points={
         'console_scripts': [