Make logging tests deterministic (#424)

The current iteration of the tests are constantly racing against each other because they touch the same file paths. Tests are run in parallel for speed reasons and there is no guarantee that 2 test methods aren't running at the same time. This commit fixes these issues by using tempfiles for the places the logger writes to disk. This way there is never going to be 2 files being touched by different tests at the same time. The next step here would to replace all the file usage with mocks so we don't actually write to disk. There is not really a reason to actually write out to disk and it makes the tests more complicated because we have to synchronizing the state of the FS or create a blank workspace for each test. But this isn't done here because it would require a slightly larger refactor of the tests. Co-authored-by: Eli Arbel <[email protected]>
qiskit-community · Jun 29, 2020 · 0d9487a · 0d9487a
1 parent 13133b0
commit 0d9487a
Show file tree

Hide file tree

Showing 4 changed files with 69 additions and 113 deletions.
diff --git a/qiskit/ignis/logging/ignis_logging.py b/qiskit/ignis/logging/ignis_logging.py
@@ -91,6 +91,7 @@ def log_to_file(self, **kwargs):
 
         assert(self._file_handler is not None), "file_handler is not set"
 
+        # Removing the stream handler to avoid printing to console here
         Logger.removeHandler(self, self._stream_handler)
         Logger.addHandler(self, self._file_handler)
         logstr = ""
@@ -152,22 +153,25 @@ class IgnisLogging:
     _config_file_exists = False
 
     # Making the class a Singleton
-    def __new__(cls):
+    def __new__(cls, log_config_path=None):
         if IgnisLogging._instance is None:
             IgnisLogging._instance = object.__new__(cls)
-            IgnisLogging._initialize()
+            IgnisLogging._initialize(log_config_path)
 
         return IgnisLogging._instance
 
     @staticmethod
-    def _load_config_file():
+    def _load_config_file(log_config_path=None):
         """
         Load and parse the config file
         Returns:
             dict: A dictionary containing all the settings
         """
-        config_file_path = os.path.join(os.path.expanduser('~'),
-                                        ".qiskit", "logging.yaml")
+        if not log_config_path:
+            config_file_path = os.path.join(os.path.expanduser('~'),
+                                            ".qiskit", "logging.yaml")
+        else:
+            config_file_path = log_config_path
         config = dict()
         if os.path.exists(config_file_path):
             with open(config_file_path, "r") as log_file:
@@ -183,13 +187,13 @@ def _load_config_file():
         return config
 
     @staticmethod
-    def _initialize():
+    def _initialize(log_config_path):
         """
         Initialize the logging facility for Ignis
         """
         logging.setLoggerClass(IgnisLogger)
 
-        log_config = IgnisLogging._load_config_file()
+        log_config = IgnisLogging._load_config_file(log_config_path)
         # Reading the config file content
         IgnisLogging._file_logging_enabled = \
             log_config.get('file_logging') == "true"
@@ -202,6 +206,19 @@ def _initialize():
         IgnisLogging._max_rotations = int(max_rotations) if \
             max_rotations is not None and max_rotations.isdigit() else 0
 
+    @staticmethod
+    def _reset_to_defaults(name):
+        if IgnisLogging._instance is not None:
+            IgnisLogging._instance = None
+            IgnisLogging._file_logging_enabled = False
+            IgnisLogging._log_file = None
+            IgnisLogging._config_file_exists = False
+            logger = logging.getLogger(name)
+            if isinstance(logger, IgnisLogger):
+                logger._file_handler = None
+                logger._file_logging_enabled = False
+                logger.removeHandler(logger._stream_handler)
+
     def get_logger(self, name: str) -> IgnisLogger:
         """
         Return an IgnisLogger object

diff --git a/requirements-dev.txt b/requirements-dev.txt
@@ -12,3 +12,4 @@ jupyter
 jupyter-sphinx
 reno
 matplotlib
+pyfakefs
diff --git a/test/logging_test/test_logging.py b/test/logging_test/test_logging.py
@@ -12,6 +12,8 @@
 # copyright notice, and modified files need to carry a notice indicating
 # that they have been altered from the originals.
 
+# pylint: disable=invalid-name
+
 
 """
 Unit testing of the Ignis Logging facility. Covering the following specs:
@@ -36,75 +38,36 @@
 
 
 """
-import unittest
 import os
+import unittest
+from pyfakefs import fake_filesystem_unittest
 from qiskit.ignis.logging import IgnisLogging, IgnisLogReader
 
 
-class TestLoggingBase(unittest.TestCase):
-    """
-    Base class for the logging test classes
-    """
-    _qiskit_dir = ""
+class TestLogging(fake_filesystem_unittest.TestCase):
+    """Test logging module"""
+    _config_file = ""
     _default_log = "ignis.log"
 
-    def __init__(self, *args, **kwargs):
-        unittest.TestCase.__init__(self, *args, **kwargs)
-        self._qiskit_dir = os.path.join(os.path.expanduser('~'), ".qiskit")
-
     def setUp(self):
         """
         Basic setup - making the .qiskit dir and preserving any existing files
         :return:
         """
-        os.makedirs(self._qiskit_dir, exist_ok=True)
-
-        # Protecting the original files, if exist
-        _safe_rename_file(os.path.join(self._qiskit_dir, "logging.yaml"),
-                          os.path.join(self._qiskit_dir, "logging.yaml.orig"))
-        # Assuming isnis.log for the default log file, as hard coded
-        _safe_rename_file(self._default_log, self._default_log + ".orig")
+        self.setUpPyfakefs()
+        super().setUp()
+        qiskit_dir = os.path.join(os.path.expanduser('~'), ".qiskit")
+        self._config_file = os.path.join(qiskit_dir, "logging.yaml")
+        os.makedirs(qiskit_dir, exist_ok=True)
 
     def tearDown(self):
         """
-        Remove auto-generated files, resurrecting original files, and
-        resetting the IgnisLogging singleton state
-
-        :return:
+          resetting the IgnisLogging singleton state
         """
-        try:
-            os.remove("logging.yaml")
-        except OSError:
-            pass
-
-        # Resurrecting the original files
-        _safe_rename_file(
-            os.path.join(self._qiskit_dir, "logging.yaml.orig"),
-            os.path.join(self._qiskit_dir, "logging.yaml"))
-
-        _safe_rename_file(self._default_log + ".orig", self._default_log)
-
-        # Resetting the following attributes, to make the singleton reset
-        IgnisLogging().get_logger(__name__).__init__(__name__)
-        IgnisLogging._instance = None  # pylint: disable=W0212
-        IgnisLogging._file_logging_enabled = False  # pylint: disable=W0212
-        IgnisLogging._log_file = None  # pylint: disable=W0212
-        IgnisLogging._config_file_exists = False  # pylint: disable=W0212
-
-
-def _safe_rename_file(src, dst):
-    try:
-        os.replace(src, dst)
-    except FileNotFoundError:
-        pass
-    except OSError:
-        pass
-
-
-class TestLoggingConfiguration(TestLoggingBase):
-    """
-    Testing configuration file handling
-    """
+        IgnisLogging._reset_to_defaults(__name__)
+
+        super().tearDown()
+
     def test_no_config_file(self):
         """
         Test there are no config file
@@ -120,8 +83,8 @@ def test_file_logging_typo(self):
         Only tests the main param: file_logging
         :return:
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging1: true")
+        with open(self._config_file, 'w') as fd:
+            fd.write("file_logging1: true")
 
         logger = IgnisLogging().get_logger(__name__)
         logger.log_to_file(test="test")
@@ -133,8 +96,8 @@ def test_file_true_typo(self):
         Only tests the main param: file_logging
         :return:
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging: tru")
+        with open(self._config_file, "w") as fd:
+            fd.write("file_logging: tru")
 
         logger = IgnisLogging().get_logger(__name__)
         logger.log_to_file(test="test")
@@ -146,45 +109,39 @@ def test_log_file_path(self):
         test that a custom log file path is honored
         :return:
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging: true\nlog_file: test_log.log")
+        log_path = "test_log.log"
+        with open(self._config_file, "w") as fd:
+            fd.write("file_logging: true\nlog_file: %s\n" % log_path)
 
         logger = IgnisLogging().get_logger(__name__)
         logger.log_to_file(test="test")
 
-        self.assertTrue(os.path.exists("test_log.log"))
-        try:
-            os.remove("test_log.log")
-        except OSError:
-            pass
+        self.assertTrue(os.path.exists(log_path))
 
     def test_file_rotation(self):
         """
         Test that the file rotation is working
-        :return:
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging: true\n"
-                       "max_size: 10\n"
-                       "max_rotations: 3")
+        log_path = 'test_log_rotate.log'
+        with open(self._config_file, "w") as fd:
+            fd.write("file_logging: true\n"
+                     "max_size: 10\n"
+                     "max_rotations: 3\n"
+                     "log_file: %s" % log_path)
 
         logger = IgnisLogging().get_logger(__name__)
+
         for i in range(100):
             logger.log_to_file(test="test%d" % i)
 
-        self.assertTrue(os.path.exists(self._default_log))
-        self.assertTrue(os.path.exists(self._default_log + ".1"))
-        self.assertTrue(os.path.exists(self._default_log + ".2"))
-        self.assertTrue(os.path.exists(self._default_log + ".3"))
-
-        list(map(os.remove, [self._default_log + ".1",
-                             self._default_log + ".2",
-                             self._default_log + ".3"]))
+        self.assertTrue(os.path.exists(log_path))
+        self.assertTrue(os.path.exists(log_path + ".1"))
+        self.assertTrue(os.path.exists(log_path + ".2"))
+        self.assertTrue(os.path.exists(log_path + ".3"))
 
     def test_manual_enabling(self):
         """
         Test that enabling the logging manually works
-        :return:
         """
         logger = IgnisLogging().get_logger(__name__)
         logger.enable_file_logging()
@@ -195,22 +152,16 @@ def test_manual_enabling(self):
     def test_manual_disabling(self):
         """
         Test that disabling the logging manually works
-        :return:
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging: true\n")
+        with open(self._config_file, "w") as fd:
+            fd.write("file_logging: true\n")
 
         logger = IgnisLogging().get_logger(__name__)
         logger.disable_file_logging()
         logger.log_to_file(test="test")
 
         self.assertFalse(os.path.exists(self._default_log))
 
-
-class TestFileLogging(TestLoggingBase):
-    """
-    Testing logging actions
-    """
     def test_save_line(self):
         """
         Test basic log operations
@@ -234,6 +185,7 @@ def test_format(self):
         logger.log_to_file(test="test")
 
         with open(self._default_log, 'r') as file:
+
             self.assertRegex(
                 file.read(),
                 r"\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} ignis_logging \S+")
@@ -253,23 +205,12 @@ def test_multiple_lines(self):
 
         self.assertGreaterEqual(len(lines), 2)
 
-
-class TestLogReader(TestLoggingBase):
-    """
-    Testing the IgnisLogReader class
-    """
-    def setUp(self):
-        TestLoggingBase.setUp(self)
-
-    def tearDown(self):
-        TestLoggingBase.tearDown(self)
-
     def test_read_multiple_files(self):
         """
         Test reading multiple lines
         """
-        with open(os.path.join(self._qiskit_dir, "logging.yaml"), "w") as file:
-            file.write("file_logging: true\nmax_size: 40\nmax_rotations: 5")
+        with open(self._config_file, "w") as fd:
+            fd.write("file_logging: true\nmax_size: 40\nmax_rotations: 5\n")
 
         logger = IgnisLogging().get_logger(__name__)
         for i in range(10):
@@ -279,17 +220,12 @@ def test_read_multiple_files(self):
         files = reader.get_log_files()
         self.assertEqual(len(files), 6)
 
-        for file in reader.get_log_files():
-            try:
-                os.remove(file)
-            except OSError:
-                pass
-
     def test_filtering(self):
         """
         Test filtering operations
         """
         with open(self._default_log, 'w') as log:
+
             log.write(
                 "2019/08/04 13:27:04 ignis_logging \'k1\':\'d1\'\n"
                 "2019/08/04 13:27:05 ignis_logging \'k1\':\'d2\'\n"

diff --git a/tox.ini b/tox.ini
@@ -26,6 +26,7 @@ deps =
     qiskit-aer
     ddt>=1.2.0,!=1.4.0
     stestr>=2.5.0
+    pyfakefs
 commands =
     pip check
     stestr run {posargs}
@@ -40,6 +41,7 @@ deps =
   pycodestyle
   pylint
   setuptools>=40.1.0
+  pyfakefs
 commands =
   pycodestyle qiskit/ignis test/
   pylint -rn -j 0 --rcfile={toxinidir}/.pylintrc qiskit/ignis test/