[IMP] runbot: improve make_result

The "Error or traceback found in logs" message is sometimes confusing
since we don't know what is the cause of the issue.

The first idea is to split the two concept, error and traceback to have
a better idea of the cause of the issue

The second one will also log the content of the line in the error
message. For traceback, tries to get the complete traceback, getting all
indentend lines and one last non idented one.

While working on it, cleaning slighty to partially get rid of
returning a dict, artefact from odoo < 13.0

runbot/common.py

@@ -70,8 +70,8 @@ def rfind(filename, pattern):
     if os.path.isfile(filename):
         regexp = re.compile(pattern, re.M)
         with file_open(filename, 'r') as f:
-            if regexp.findall(f.read()):
+            result = regexp.findall(f.read())
-                return True
+            return result or False
     return False
 
 

runbot/models/build_config.py

@@ -23,7 +23,6 @@ _SAFE_OPCODES |= set(to_opcodes(['LOAD_DEREF', 'STORE_DEREF', 'LOAD_CLOSURE']))
 
 _logger = logging.getLogger(__name__)
 
-_re_error = r'^(?:\d{4}-\d\d-\d\d \d\d:\d\d:\d\d,\d{3} \d+ (?:ERROR|CRITICAL) )|(?:Traceback \(most recent call last\):)$'
 _re_warning = r'^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d,\d{3} \d+ WARNING '
 
 PYTHON_DEFAULT = "# type python code here\n\n\n\n\n\n"
@@ -926,17 +925,19 @@ class ConfigStep(models.Model):
         log_time = self._get_log_last_write(build)
         if log_time:
             build.job_end = log_time
-        if self.job_type == 'python' and self.python_result_code and self.python_result_code != PYTHON_DEFAULT:
+        if self.job_type == 'python':
-            build.write(self._make_python_results(build))
+            if self.python_result_code and self.python_result_code != PYTHON_DEFAULT:
-        elif self.job_type in ['install_odoo', 'python']:
+                self._make_python_results(build)
+            elif self.test_enable or self.test_tags:
+                self._make_odoo_results(build)
+        elif self.job_type == 'install_odoo':
             if self.coverage:
                 build.write(self._make_coverage_results(build))
-            if self.test_enable or self.test_tags:
+            self._make_odoo_results(build)
-                build.write(self._make_tests_results(build))
         elif self.job_type == 'test_upgrade':
-            build.write(self._make_upgrade_results(build))
+            self._make_upgrade_results(build)
         elif self.job_type == 'restore':
-            build.write(self._make_restore_results(build))
+            self._make_restore_results(build)
 
     def _make_python_results(self, build):
         eval_ctx = self._make_python_ctx(build)
@@ -945,7 +946,7 @@ class ConfigStep(models.Model):
         # todo check return_value or write in try except. Example: local result setted to wrong value
         if not isinstance(return_value, dict):
             raise RunbotException('python_result_code must set return_value to a dict values on build')
-        return return_value
+        build.write(return_value)  # old style support
 
     def _make_coverage_results(self, build):
         build_values = {}
@@ -965,22 +966,18 @@ class ConfigStep(models.Model):
         return build_values
 
     def _make_upgrade_results(self, build):
-        build_values = {}
         build._log('upgrade', 'Getting results for build %s' % build.dest)
 
         if build.local_result != 'ko':
             checkers = [
                 self._check_log,
-                self._check_module_loaded,
                 self._check_error,
+                self._check_module_loaded,
                 self._check_module_states,
                 self._check_build_ended,
                 self._check_warning,
             ]
-            local_result = self._get_checkers_result(build, checkers)
+            build.local_result = self._get_checkers_result(build, checkers)
-            build_values['local_result'] = build._get_worst_result([build.local_result, local_result])
-
-        return build_values
 
     def _check_module_states(self, build):
         if not build._is_file('logs/modules_states.txt'):
@@ -1009,9 +1006,18 @@ class ConfigStep(models.Model):
 
     def _check_error(self, build, regex=None):
         log_path = build._path('logs', '%s.txt' % self.name)
-        regex = regex or _re_error
+        re_error = regex or r'^(?:\d{4}-\d\d-\d\d \d\d:\d\d:\d\d,\d{3} \d+ (?:ERROR|CRITICAL) .*)$'
-        if rfind(log_path, regex):
+
-            build._log('_make_tests_results', 'Error or traceback found in logs', level="ERROR")
+        if result := rfind(log_path, re_error):
+            build._log('_make_tests_results', 'Error found in logs:\n%s' % '\n'.join(result), level="ERROR")
+            return 'ko'
+
+        re_traceback = r'^(?:Traceback \(most recent call last\):)$'
+        if result := rfind(log_path, re_traceback):
+            # find Traceback, all following indented lines and one last non indented line
+            complete_traceback = rfind(log_path, r'^(?:Traceback \(most recent call last\):(?:\n .*)*(?:\n.*)?)')[:10000]
+            complete_traceback = complete_traceback or result
+            build._log('_make_tests_results', 'Traceback found in logs:\n%s' % '\n'.join(complete_traceback), level="ERROR")
             return 'ko'
         return 'ok'
 
@@ -1049,34 +1055,28 @@ class ConfigStep(models.Model):
                 return result
         return 'ok'
 
-    def _make_tests_results(self, build):
+    def _make_odoo_results(self, build):
-        build_values = {}
         build._log('run', 'Getting results for build %s' % build.dest)
 
         if build.local_result != 'ko':
             checkers = [
                 self._check_log,
-                self._check_module_loaded,
                 self._check_error,
-                self._check_build_ended
+                self._check_module_loaded,
+                self._check_build_ended,
             ]
             if build.local_result != 'warn':
                 checkers.append(self._check_warning)
 
-            local_result = self._get_checkers_result(build, checkers)
+            build.local_result = self._get_checkers_result(build, checkers)
-            build_values['local_result'] = build._get_worst_result([build.local_result, local_result])
-        return build_values
 
     def _make_restore_results(self, build):
-        build_values = {}
         if build.local_result != 'warn':
             checkers = [
                 self._check_log,
                 self._check_restore_ended
             ]
-            local_result = self._get_checkers_result(build, checkers)
+            build.local_result = self._get_checkers_result(build, checkers)
-            build_values['local_result'] = build._get_worst_result([build.local_result, local_result])
-        return build_values
 
     def _make_stats(self, build):
         if not self.make_stats:  # TODO garbage collect non sticky stat

runbot/models/repo.py

@@ -90,7 +90,7 @@ class Trigger(models.Model):
 
     report_view_id = fields.Many2one('ir.ui.view',
                                   help="custom view to render result",
-                                  string='Docker Template',
+                                  string='Report view',
                                   domain=[('type', '=', 'qweb')],
                                   context={'default_type': 'qweb', 'default_arch_base': '<t></t>'},
     )

runbot/tests/test_build_config_step.py

@@ -618,102 +618,128 @@ class TestMakeResult(RunbotCase):
         super(TestMakeResult, self).setUp()
         self.ConfigStep = self.env['runbot.build.config.step']
         self.Config = self.env['runbot.build.config']
+        self.patchers['getmtime'].return_value = 7200
+        self.logs = []
+        def _log(build, func, message, level='INFO', log_type='runbot', path='runbot'):
+            self.logs.append((level, message))
 
-    @patch('odoo.addons.runbot.models.build_config.os.path.getmtime')
+        self.start_patcher('log_patcher', 'odoo.addons.runbot.models.build.BuildResult._log', new=_log)
-    @patch('odoo.addons.runbot.models.build.BuildResult._log')
+
-    def test_make_result(self, mock_log, mock_getmtime):
+        self.build = self.Build.create({
+            'params_id': self.base_params.id,
+        })
+        self.config_step = self.ConfigStep.create({
+            'name': 'all',
+            'job_type': 'install_odoo',
+            'test_tags': '/module,:class.method',
+        })
+
+    def test_make_result_ok(self):
         file_content = """
 Loading stuff
 odoo.stuff.modules.loading: Modules loaded.
 Some post install stuff
 Initiating shutdown
 """
-        logs = []
-
-        def _log(func, message, level='INFO', log_type='runbot', path='runbot'):
-            logs.append((level, message))
-
-        mock_log.side_effect = _log
-        mock_getmtime.return_value = 7200
-
-        config_step = self.ConfigStep.create({
-            'name': 'all',
-            'job_type': 'install_odoo',
-            'test_tags': '/module,:class.method',
-        })
-        build = self.Build.create({
-            'params_id': self.base_params.id,
-        })
-        logs = []
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(logs, [('INFO', 'Getting results for build %s' % build.dest)])
+        self.assertEqual(self.logs, [('INFO', 'Getting results for build %s' % self.build.dest)])
-        self.assertEqual(build.local_result, 'ok')
+        self.assertEqual(self.build.local_result, 'ok')
-        # no shutdown
+
-        build = self.Build.create({
+    def test_make_result_no_shutdown(self):
-            'params_id': self.base_params.id,
-        })
-        logs = []
         file_content = """
 Loading stuff
 odoo.stuff.modules.loading: Modules loaded.
 Some post install stuff
         """
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(build.local_result, 'ko')
+        self.assertEqual(self.build.local_result, 'ko')
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest),
+            ('INFO', 'Getting results for build %s' % self.build.dest),
-            ('ERROR', 'No "Initiating shutdown" found in logs, maybe because of cpu limit.')
+            ('ERROR', 'No "Initiating shutdown" found in logs, maybe because of cpu limit.'),
         ])
-        # no loaded
+
-        build = self.Build.create({
+    def test_make_result_no_loaded(self):
-            'params_id': self.base_params.id,
-        })
-        logs = []
         file_content = """
 Loading stuff
 """
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(build.local_result, 'ko')
+        self.assertEqual(self.build.local_result, 'ko')
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest),
+            ('INFO', 'Getting results for build %s' % self.build.dest),
-            ('ERROR', 'Modules loaded not found in logs')
+            ('ERROR', 'Modules loaded not found in logs'),
         ])
 
-        # traceback
+    def test_make_result_traceback(self):
-        build = self.Build.create({
+        file_content = """
-            'params_id': self.base_params.id,
+Loading stuff
-        })
+Traceback (most recent call last):
-        logs = []
+  File "/data/build/odoo/odoo-bin", line 5, in <module>
+    import odoo
+  File "/data/build/odoo/odoo/__init__.py", line 134, in <module>
+    from . import modules
+  File "/data/build/odoo/odoo/modules/__init__.py", line 8, in <module>
+    from . import db, graph, loading, migration, module, registry, neutralize
+  File "/data/build/odoo/odoo/modules/graph.py", line 11, in <module>
+    import odoo.tools as tools
+  File "/data/build/odoo/odoo/tools/__init__.py", line 25, in <module>
+    from .mail import *
+  File "/data/build/odoo/odoo/tools/mail.py", line 32, in <module>
+    safe_attrs = clean.defs.safe_attrs | frozenset(
+AttributeError: module 'lxml.html.clean' has no attribute 'defs'
+2024-05-14 09:54:22,692 17 INFO dbname path.to.test: aaa
+"""
+        with patch('builtins.open', mock_open(read_data=file_content)):
+            self.config_step._make_results(self.build)
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(self.build.local_result, 'ko')
+        expected = """Traceback found in logs:
+Traceback (most recent call last):
+  File "/data/build/odoo/odoo-bin", line 5, in <module>
+    import odoo
+  File "/data/build/odoo/odoo/__init__.py", line 134, in <module>
+    from . import modules
+  File "/data/build/odoo/odoo/modules/__init__.py", line 8, in <module>
+    from . import db, graph, loading, migration, module, registry, neutralize
+  File "/data/build/odoo/odoo/modules/graph.py", line 11, in <module>
+    import odoo.tools as tools
+  File "/data/build/odoo/odoo/tools/__init__.py", line 25, in <module>
+    from .mail import *
+  File "/data/build/odoo/odoo/tools/mail.py", line 32, in <module>
+    safe_attrs = clean.defs.safe_attrs | frozenset(
+AttributeError: module 'lxml.html.clean' has no attribute 'defs'"""
+        self.assertEqual(self.logs, [
+            ('INFO', 'Getting results for build %s' % self.build.dest),
+            ('ERROR', expected),
+        ])
+
+    def test_make_result_error(self):
         file_content = """
 Loading stuff
 odoo.stuff.modules.loading: Modules loaded.
 Some post install stuff
-2019-12-17 17:34:37,692 17 ERROR dbname path.to.test: FAIL: TestClass.test_
+2024-05-14 09:54:22,692 17 ERROR dbname path.to.test: FAIL: TestClass.test_
-Traceback (most recent call last):
+Some log
-File "x.py", line a, in test_
+2024-05-14 09:54:22,692 17 ERROR dbname path.to.test: FAIL: TestClass.test2_
-    ....
 Initiating shutdown
 """
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(build.local_result, 'ko')
+        self.assertEqual(self.build.local_result, 'ko')
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest),
+            ('INFO', 'Getting results for build %s' % self.build.dest),
-            ('ERROR', 'Error or traceback found in logs')
+            ('ERROR', """Error found in logs:
+2024-05-14 09:54:22,692 17 ERROR dbname path.to.test: FAIL: TestClass.test_
+2024-05-14 09:54:22,692 17 ERROR dbname path.to.test: FAIL: TestClass.test2_"""),
         ])
 
-        # warning in logs
+    def test_make_result_warning(self):
-        build = self.Build.create({
-            'params_id': self.base_params.id,
-        })
-        logs = []
         file_content = """
 Loading stuff
 odoo.stuff.modules.loading: Modules loaded.
@@ -722,30 +748,26 @@ Some post install stuff
 Initiating shutdown
 """
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(build.local_result, 'warn')
+        self.assertEqual(self.build.local_result, 'warn')
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest),
+            ('INFO', 'Getting results for build %s' % self.build.dest),
             ('WARNING', 'Warning found in logs')
         ])
 
         # no log file
-        logs = []
+        self.logs = []
         self.patchers['isfile'].return_value = False
-        config_step._make_results(build)
+        self.config_step._make_results(self.build)
 
-        self.assertEqual(build.local_result, 'ko')
+        self.assertEqual(self.build.local_result, 'ko')
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest),
+            ('INFO', 'Getting results for build %s' % self.build.dest),
             ('ERROR', 'Log file not found at the end of test job')
         ])
 
-        # no error but build was already in warn
+    def test_make_result_already_warn(self):
-        build = self.Build.create({
-            'params_id': self.base_params.id,
-        })
-        logs = []
         file_content = """
 Loading stuff
 odoo.stuff.modules.loading: Modules loaded.
@@ -753,17 +775,18 @@ Some post install stuff
 Initiating shutdown
 """
         self.patchers['isfile'].return_value = True
-        build.local_result = 'warn'
+        self.build.local_result = 'warn'
         with patch('builtins.open', mock_open(read_data=file_content)):
-            config_step._make_results(build)
+            self.config_step._make_results(self.build)
-        self.assertEqual(logs, [
+        self.assertEqual(self.logs, [
-            ('INFO', 'Getting results for build %s' % build.dest)
+            ('INFO', 'Getting results for build %s' % self.build.dest)
         ])
-        self.assertEqual(str(build.job_end), '1970-01-01 02:00:00')
+        self.assertEqual(str(self.build.job_end), '1970-01-01 02:00:00')
-        self.assertEqual(build.local_result, 'warn')
+        self.assertEqual(self.build.local_result, 'warn')
 
-    @patch('odoo.addons.runbot.models.build_config.ConfigStep._make_tests_results')
+
-    def test_make_python_result(self, mock_make_tests_results):
+    @patch('odoo.addons.runbot.models.build_config.ConfigStep._make_odoo_results')
+    def test_make_python_result(self, mock_make_odoo_results):
         config_step = self.ConfigStep.create({
             'name': 'all',
             'job_type': 'python',
@@ -785,7 +808,10 @@ Initiating shutdown
 
         # no result defined
         config_step.python_result_code = ""
-        mock_make_tests_results.return_value = {'local_result': 'warn'}
+        def make_warn(build):
+            build.local_result = "warn"
+
+        mock_make_odoo_results.side_effect = make_warn
         config_step._make_results(build)
         self.assertEqual(build.local_result, 'warn')