log_helper: Test and improve error-handling

If there is an error in log-handling (e.g. wrong args to logger call) do not fail or raise but produce something helpful

log_helper: Test and improve error-handling
If there is an error in log-handling (e.g. wrong args to logger call) do not fail or raise but produce something helpful
Christian Herdtweck
1 parent 7f315674
Showing 3 changed files with 28 additions and 5 deletions
oletools/common/log_helper/_json_formatter.py
tests/common/log_helper/log_helper_test_main.py
tests/common/log_helper/test_log_helper.py
@@ -32,15 +32,25 @@ class JsonFormatter(logging.Formatter):
         :py:class:`oletools.common.log_helper.OletoolsLoggerAdapter` or added here
         (for input from e.g. captured warnings, third-party libraries)
         """
-        msg = self.msg_formatter.format(record)
-        json_dict = dict(msg=msg.replace('\n', ' '), level=record.levelname)
+        json_dict = dict(msg='', level='', type='')
         try:
+            msg = self.msg_formatter.format(record)
+            json_dict['msg'] = msg.replace('\n', ' ')
+            json_dict['level'] = record.levelname
             json_dict['type'] = record.type
-        except AttributeError:
-            if record.name == 'py.warnings':   # this is the name of the logger
+        except AttributeError:     # most probably: record has no "type" field
+            if record.name == 'py.warnings':   # this is from python's warning-capture logger
                 json_dict['type'] = 'warning'
             else:
-                json_dict['type'] = 'msg'
+                json_dict['type'] = 'msg'      # message of unknown origin
+        except Exception as exc:
+            try:
+                json_dict['msg'] = "Ignore {0} when formatting '{1}': {2}".format(type(exc), record.msg, exc)
+            except Exception as exc2:
+                json_dict['msg'] = 'Caught {0} in logging'.format(str(exc2))
+            json_dict['type'] = 'log-warning'
+            json_dict['level'] = 'warning'
+
         formatted_message = '    ' + json.dumps(json_dict)
         if self._is_first_line:
@@ -50,6 +50,7 @@ def main(args):
     percent_autoformat = '%-autoformat' in args
     warn = 'warn' in args
     exc_info = 'exc-info' in args
+    wrong_log_args = 'wrong-log-args' in args
     log_helper_test_imported.logger.setLevel(logging.ERROR)
@@ -71,6 +72,12 @@ def main(args):
         except Exception:
             logger.exception('Caught exception')  # has exc_info=True
+    if wrong_log_args:
+        logger.info('Opening file /dangerous/file/with-%s-in-name')
+        logger.info('The result is %f')
+        logger.info('No result', 1.23)
+        logger.info('The result is %f', 'bla')
+
     log_helper.end_logging()
@@ -224,6 +224,12 @@ class TestLogHelper(unittest.TestCase):
         self.assertIn('Traceback (most recent call last)', output)    # start of trace
         self.assertIn(TEST_FILE, output)        # part of trace
+    def test_json_wrong_args(self):
+        """Test that too many or missing args do not raise exceptions inside logger"""
+        output = self._run_test(['enable', 'as-json', 'wrong-log-args', 'info'])
+        json.loads(output)    # check that this does not raise, so json is valid
+        # do not care about actual contents of output
+
     def _assert_json_messages(self, output, messages):
         try:
             json_data = json.loads(output)