Log traceback and related exceptions (#324)

python/publish/github_action.py

@@ -1,6 +1,7 @@
 import logging
 import os
 import sys
+import traceback
 from io import TextIOWrapper
 from typing import Mapping, Any, Optional
 
@@ -62,11 +63,40 @@ def warning(self, message: str, file: Optional[str] = None, line: Optional[int]
             params.update(col=column)
         self._command(self._file, 'warning', message, params)
 
+    def _exception(self, te: traceback.TracebackException):
+        def exception_str(te: traceback.TracebackException) -> str:
+            # we take the last line, which ends with a newline, that we strip
+            return list(te.format_exception_only())[-1].split('\n')[0]
+
+        self.error('{te}{caused}{context}'.format(
+            te=exception_str(te),
+            caused=f'  caused by  {exception_str(te.__cause__)}' if te.__cause__ else '',
+            context=f'  while handling  {exception_str(te.__context__)}' if te.__context__ else ''
+        ), exception=None)
+
+        for lines in te.format(chain=False):
+            for line in lines.split('\n'):
+                if line:
+                    logger.debug(line)
+
+        cause = te.__cause__
+        while cause:
+            self._exception(cause)
+            cause = cause.__cause__
+
+        context = te.__context__
+        while context:
+            self._exception(context)
+            context = context.__context__
+
     def error(self,
               message: str,
               file: Optional[str] = None, line: Optional[int] = None, column: Optional[int] = None,
               exception: Optional[BaseException] = None):
-        logger.error(message, exc_info=exception)
+        if exception:
+            self._exception(traceback.TracebackException.from_exception(exception))
+        else:
+            logger.error(message)
 
         params = {}
         if file is not None:
@@ -79,6 +109,9 @@ def error(self,
 
     @staticmethod
     def _command(file: TextIOWrapper, command: str, value: str = '', params: Optional[Mapping[str, Any]] = None):
+        # take first line of value if multiline
+        value = value.split('\n', 1)[0]
+
         if params is None:
             params = {}
         params = ','.join([f'{key}={str(value)}'

python/publish_unit_test_results.py

@@ -16,13 +16,14 @@
 import publish.github_action
 from publish import available_annotations, default_annotations, \
     pull_request_build_modes, fail_on_modes, fail_on_mode_errors, fail_on_mode_failures, \
-    comment_mode_off, comment_mode_always, comment_modes, punctuation_space
+    comment_mode_always, comment_modes, punctuation_space
 from publish.github_action import GithubAction
 from publish.junit import parse_junit_xml_files, process_junit_xml_elems
 from publish.progress import progress_logger
 from publish.publisher import Publisher, Settings
 from publish.retry import GitHubRetry
-from publish.unittestresults import get_test_results, get_stats, ParsedUnitTestResults, ParsedUnitTestResultsWithCommit
+from publish.unittestresults import get_test_results, get_stats, ParsedUnitTestResults, ParsedUnitTestResultsWithCommit, \
+    ParseError
 
 logger = logging.getLogger('publish')
 
@@ -123,6 +124,11 @@ def parse_files(settings: Settings, gha: GithubAction) -> ParsedUnitTestResultsW
     return process_junit_xml_elems(elems, settings.time_factor).with_commit(settings.commit)
 
 
+def log_parse_errors(errors: List[ParseError], gha: GithubAction):
+    [gha.error(message=f'Error processing result file: {error.message}', file=error.file, line=error.line, column=error.column, exception=error.exception)
+     for error in errors]
+
+
 def main(settings: Settings, gha: GithubAction) -> None:
     # we cannot create a check run or pull request comment when running on pull_request event from a fork
     # when event_file is given we assume proper setup as in README.md#support-fork-repositories-and-dependabot-branches
@@ -144,8 +150,7 @@ def main(settings: Settings, gha: GithubAction) -> None:
 
     # get the unit test results
     parsed = parse_files(settings, gha)
-    [gha.error(message=f'Error processing result file: {error.message}', file=error.file, line=error.line, column=error.column, exception=error.exception)
-     for error in parsed.errors]
+    log_parse_errors(parsed.errors, gha)
 
     # process the parsed results
     results = get_test_results(parsed, settings.dedup_classes_by_file_name)

python/test/test_action_script.py

@@ -1,3 +1,5 @@
+import io
+import re
 import json
 import logging
 import os
@@ -6,15 +8,16 @@
 import tempfile
 import unittest
 from typing import Optional, Union, List, Type
+
 import mock
 
 from publish import pull_request_build_mode_merge, fail_on_mode_failures, fail_on_mode_errors, \
-    fail_on_mode_nothing, comment_modes, comment_mode_off, comment_mode_always, \
+    fail_on_mode_nothing, comment_modes, comment_mode_always, \
     pull_request_build_modes, punctuation_space
 from publish.github_action import GithubAction
 from publish.unittestresults import ParsedUnitTestResults, ParseError
 from publish_unit_test_results import get_conclusion, get_commit_sha, get_var, \
-    check_var, check_var_condition, deprecate_var, deprecate_val, \
+    check_var, check_var_condition, deprecate_var, deprecate_val, log_parse_errors, \
     get_settings, get_annotations_config, Settings, get_files, throttle_gh_request_raw, is_float, parse_files, main
 from test_utils import chdir
 
@@ -803,8 +806,7 @@ def test_parse_files(self):
                                      trx_files_glob=str(test_files_path / 'trx' / '**' / '*.trx'))
         actual = parse_files(settings, gha)
 
-        gha.warning.assert_not_called()
-        gha.error.assert_not_called()
+        self.assertEqual([], gha.method_calls)
 
         self.assertEqual(65, actual.files)
         self.assertEqual(6, len(actual.errors))
@@ -817,6 +819,28 @@ def test_parse_files(self):
         self.assertEqual(1858, len(actual.cases))
         self.assertEqual('commit', actual.commit)
 
+        with io.StringIO() as string:
+            gha = GithubAction(file=string)
+            with mock.patch('publish.github_action.logger') as m:
+                log_parse_errors(actual.errors, gha)
+            self.assertEqual(
+                sorted([
+                    "::error::lxml.etree.XMLSyntaxError: Start tag expected, '<' not found, line 1, column 1",
+                    "::error file=non-xml.xml::Error processing result file: Start tag expected, '<' not found, line 1, column 1 (non-xml.xml, line 1)",
+                    "::error::Exception: File is empty.",
+                    "::error file=empty.xml::Error processing result file: File is empty.",
+                    "::error::lxml.etree.XMLSyntaxError: Premature end of data in tag skipped line 9, line 11, column 22",
+                    "::error file=corrupt-xml.xml::Error processing result file: Premature end of data in tag skipped line 9, line 11, column 22 (corrupt-xml.xml, line 11)",
+                    "::error::junitparser.junitparser.JUnitXmlError: Invalid format.",
+                    "::error file=non-junit.xml::Error processing result file: Invalid format.",
+                    "::error::lxml.etree.XMLSyntaxError: Char 0x0 out of allowed range, line 33, column 16",
+                    "::error file=NUnit-issue17521.xml::Error processing result file: Char 0x0 out of allowed range, line 33, column 16 (NUnit-issue17521.xml, line 33)",
+                    "::error::lxml.etree.XMLSyntaxError: attributes construct error, line 5, column 109",
+                    "::error file=NUnit-issue47367.xml::Error processing result file: attributes construct error, line 5, column 109 (NUnit-issue47367.xml, line 5)"
+                ]), sorted([re.sub(r'file=.*[/\\]', 'file=', re.sub(r'[(]file:.*/', '(', line)) for line in string.getvalue().split(os.linesep) if line])
+            )
+            # self.assertEqual([], m.method_calls)
+
     def test_parse_files_no_matches(self):
         gha = mock.MagicMock()
         with tempfile.TemporaryDirectory() as path:

python/test/test_github_action.py

@@ -1,5 +1,6 @@
 import io
 import os
+import re
 import tempfile
 import unittest
 from contextlib import contextmanager
@@ -93,6 +94,93 @@ def test_error(self):
         with gh_action_command_test(self, '::error file=the file,line=1,col=2::the message') as gha:
             gha.error('the message', file='the file', line=1, column=2)
 
+        # log exception
+        with gh_action_command_test(self, f'::error::RuntimeError: failure{os.linesep}'
+                                          f'::error file=the file,line=1,col=2::the message') as gha:
+            try:
+                raise RuntimeError('failure')
+            except RuntimeError as e:
+                error = e
+
+            with mock.patch('publish.github_action.logger') as m:
+                gha.error('the message', file='the file', line=1, column=2, exception=error)
+
+            self.assertEqual(
+                [(call[0], re.sub(r'File ".*[/\\]', 'File "', re.sub(r'line \d+', 'line X', call.args[0])))
+                 for call in m.method_calls],
+                [
+                    ('error', 'RuntimeError: failure'),
+                    ('debug', 'Traceback (most recent call last):'),
+                    ('debug', '  File "test_github_action.py", line X, in test_error'),
+                    ('debug', "    raise RuntimeError('failure')"),
+                    ('debug', 'RuntimeError: failure')
+                ]
+            )
+
+        # log exceptions related via cause
+        with gh_action_command_test(self, f'::error::RuntimeError: failed except  caused by  ValueError: invalid value{os.linesep}'
+                                          f'::error::ValueError: invalid value{os.linesep}'
+                                          f'::error file=the file,line=1,col=2::the message') as gha:
+            error = self.get_error_with_cause()
+            with mock.patch('publish.github_action.logger') as m:
+                gha.error('the message', file='the file', line=1, column=2, exception=error)
+
+            self.assertEqual(
+                [(call[0], re.sub(r'File ".*[/\\]', 'File "', re.sub(r'line \d+', 'line X', call.args[0])))
+                 for call in m.method_calls],
+                [
+                    ('error', 'RuntimeError: failed except  caused by  ValueError: invalid value'),
+                    ('debug', 'Traceback (most recent call last):'),
+                    ('debug', '  File "test_github_action.py", line X, in get_error_with_cause'),
+                    ('debug', "    raise RuntimeError('failed except') from ValueError('invalid value')"),
+                    ('debug', 'RuntimeError: failed except'),
+                    ('error', 'ValueError: invalid value'),
+                    ('debug', 'ValueError: invalid value')
+                ]
+            )
+
+        # log exceptions related via context
+        with gh_action_command_test(self, f'::error::RuntimeError: failed except  while handling  ValueError: invalid value{os.linesep}'
+                                          f'::error::ValueError: invalid value{os.linesep}'
+                                          f'::error file=the file,line=1,col=2::the message') as gha:
+            error = self.get_error_with_context()
+            with mock.patch('publish.github_action.logger') as m:
+                gha.error('the message', file='the file', line=1, column=2, exception=error)
+
+            self.assertEqual(
+                [(call[0], re.sub(r'File ".*[/\\]', 'File "', re.sub(r'line \d+', 'line X', call.args[0])))
+                 for call in m.method_calls],
+                [
+                    ('error', 'RuntimeError: failed except  while handling  ValueError: invalid value'),
+                    ('debug', 'Traceback (most recent call last):'),
+                    ('debug', '  File "test_github_action.py", line X, in get_error_with_context'),
+                    ('debug', "    raise RuntimeError('failed except')"),
+                    ('debug', 'RuntimeError: failed except'),
+                    ('error', 'ValueError: invalid value'),
+                    ('debug', 'Traceback (most recent call last):'),
+                    ('debug', '  File "test_github_action.py", line X, in get_error_with_context'),
+                    ('debug', "    raise ValueError('invalid value')"),
+                    ('debug', 'ValueError: invalid value')
+                ]
+            )
+
+    @staticmethod
+    def get_error_with_cause() -> RuntimeError:
+        try:
+            raise RuntimeError('failed except') from ValueError('invalid value')
+        except RuntimeError as re:
+            return re
+
+    @staticmethod
+    def get_error_with_context() -> RuntimeError:
+        try:
+            raise ValueError('invalid value')
+        except ValueError:
+            try:
+                raise RuntimeError('failed except')
+            except RuntimeError as re:
+                return re
+
     def test_add_env(self):
         with gh_action_env_file_test(self, GithubAction.ENV_FILE_VAR_NAME, 'var=val\n') as gha:
             gha.add_to_env('var', 'val')
@@ -115,6 +203,11 @@ def test_add_job_summary(self):
             gha.add_to_job_summary('# title\ncontent\n')
             gha.add_to_job_summary('## subtitle\nmore content\n')
 
+    def test__command_with_multi_line_value(self):
+        with io.StringIO() as string:
+            GithubAction._command(string, 'command', 'multi\nline\nvalue')
+            self.assertEqual('::command::multi' + os.linesep, string.getvalue())
+
     def test__append_to_file_errors(self):
         # env variable does not exist
         with mock.patch.dict(os.environ, {}, clear=True):