tests: Add warnings to log_helper test

Encountered an example where a 3rd-party library issued a warning that messed up the json output. Create test to reproduce this.

tests: Add warnings to log_helper test
Encountered an example where a 3rd-party library issued a warning that messed up the json output. Create test to reproduce this.
Christian Herdtweck
1 parent 3c3b7093
Showing 3 changed files with 48 additions and 1 deletions
tests/common/log_helper/log_helper_test_imported.py
tests/common/log_helper/log_helper_test_main.py
tests/common/log_helper/test_log_helper.py
@@ -4,6 +4,7 @@ by the main test file
 """
 from oletools.common.log_helper import log_helper
+import warnings
 DEBUG_MESSAGE = 'imported: debug log'
 INFO_MESSAGE = 'imported: info log'
@@ -11,7 +12,10 @@ WARNING_MESSAGE = &#39;imported: warning log&#39;
 ERROR_MESSAGE = 'imported: error log'
 CRITICAL_MESSAGE = 'imported: critical log'
 RESULT_MESSAGE = 'imported: result log'
+
 RESULT_TYPE = 'imported: result'
+ACTUAL_WARNING = 'Feature XYZ provided by this module might be deprecated at '\
+    'some point in the future ... or not'
 logger = log_helper.get_or_create_silent_logger('test_imported')
@@ -27,3 +31,7 @@ def log():
     logger.error(ERROR_MESSAGE)
     logger.critical(CRITICAL_MESSAGE)
     logger.info(RESULT_MESSAGE, type=RESULT_TYPE)
+
+
+def warn():
+    warnings.warn(ACTUAL_WARNING)
@@ -2,6 +2,7 @@
 import sys
 import logging
+import warnings
 from tests.common.log_helper import log_helper_test_imported
 from oletools.common.log_helper import log_helper
@@ -11,7 +12,9 @@ WARNING_MESSAGE = &#39;main: warning log&#39;
 ERROR_MESSAGE = 'main: error log'
 CRITICAL_MESSAGE = 'main: critical log'
 RESULT_MESSAGE = 'main: result log'
+
 RESULT_TYPE = 'main: result'
+ACTUAL_WARNING = 'Warnings can pop up anywhere, have to be prepared!'
 logger = log_helper.get_or_create_silent_logger('test_main')
@@ -24,7 +27,8 @@ def enable_logging():
 def main(args):
     """
-    Try to cover possible logging scenarios. For each scenario covered, here's the expected args and outcome:
+    Try to cover possible logging scenarios. For each scenario covered, here's
+    the expected args and outcome:
     - Log without enabling: ['<level>']
         * logging when being imported - should never print
     - Log as JSON without enabling: ['as-json', '<level>']
@@ -35,6 +39,8 @@ def main(args):
         * logging as JSON when being run as script - should log messages as JSON
     - Enable, log as JSON and throw: ['enable', 'as-json', 'throw', '<level>']
         * should produce JSON-compatible output, even after an unhandled exception
+    - Enable, log as JSON and warn: ['enable', 'as-json', 'warn', '<level>']
+        * should produce JSON-compatible output, even after a warning
     """
     # the level should always be the last argument passed
@@ -42,6 +48,7 @@ def main(args):
     use_json = 'as-json' in args
     throw = 'throw' in args
     percent_autoformat = '%-autoformat' in args
+    warn = 'warn' in args
     log_helper_test_imported.logger.setLevel(logging.ERROR)
@@ -53,6 +60,10 @@ def main(args):
     if throw:
         raise Exception('An exception occurred before ending the logging')
+    if warn:
+        warnings.warn(ACTUAL_WARNING)
+        log_helper_test_imported.warn()
+
     log_helper.end_logging()
@@ -142,6 +142,32 @@ class TestLogHelper(unittest.TestCase):
         self.assertIn('INFO:test_main:main: info log', output)
         self.assertIn('INFO:test_imported:imported: info log', output)
+    def test_json_correct_on_warnings(self):
+        """
+        Test that even on warnings our JSON is always correct
+        """
+        output = self._run_test(['enable', 'as-json', 'warn', 'warning'])
+        expected_messages = [
+            log_helper_test_main.WARNING_MESSAGE,
+            log_helper_test_main.ERROR_MESSAGE,
+            log_helper_test_main.CRITICAL_MESSAGE,
+            log_helper_test_imported.WARNING_MESSAGE,
+            log_helper_test_imported.ERROR_MESSAGE,
+            log_helper_test_imported.CRITICAL_MESSAGE,
+        ]
+
+        for msg in expected_messages:
+            self.assertIn(msg, output)
+
+        # last two entries of output should be warnings
+        jout = json.loads(output)
+        self.assertEqual(jout[-2]['level'], 'WARNING')
+        self.assertEqual(jout[-1]['level'], 'WARNING')
+        self.assertEqual(jout[-2]['type'], 'warning')
+        self.assertEqual(jout[-1]['type'], 'warning')
+        self.assertIn(log_helper_test_main.ACTUAL_WARNING, jout[-2]['msg'])
+        self.assertIn(log_helper_test_imported.ACTUAL_WARNING, jout[-1]['msg'])
+
     def _assert_json_messages(self, output, messages):
         try:
             json_data = json.loads(output)
@@ -163,6 +189,8 @@ class TestLogHelper(unittest.TestCase):
         When arg `run_third_party` is `True`, we do not run the `TEST_FILE` as
         main moduel but the `TEST_FILE_3RD_PARTY` and return contents of
         `stderr` instead of `stdout`.
+
+        TODO: use tests.utils.call_and_capture
         """
         all_args = [PYTHON_EXECUTABLE, ]
         if run_third_party: