From 96ca0ff974cbc80bb3296bbb8e79d8eac238e384 Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Tue, 29 Nov 2022 15:47:18 +0100 Subject: [PATCH] [IMP] runbot: global state computation One of the most problematic concurrency issue is when multiple children tries to write the state/result on the parent concurrently. Multiple partial solutions are possible here: - avoid to write if the state doesn't changes - avoid to write on a build belonging to another host A maybe overkill solution would be to add a message queue for an host, signaling that one of the child state changed. An intermediate solution would be to let the host check the state of the children while there are some of them, and update the local build state assynchronously himself. We can actualy use the 'waiting' global state to now if we need to continue to check the build state and result. While a build is not done or running, we need to check all children result and state on case they were updated. One corner case is when rebuilding a child: a new child is added but the parent is maybe not in the 'waiting' global state anymore. If this is the case, we need to recusivelly change the state of the parents to waiting so that they will update again. --- runbot/container.py | 15 +- runbot/models/build.py | 353 +++++++++++++------------ runbot/models/build_config.py | 22 +- runbot/models/event.py | 9 +- runbot/models/host.py | 16 +- runbot/models/runbot.py | 76 +++--- runbot/tests/common.py | 6 +- runbot/tests/test_build.py | 169 +++++++++--- runbot/tests/test_build_config_step.py | 75 ++++-- runbot/tests/test_build_error.py | 10 +- runbot/tests/test_host.py | 4 +- runbot/tests/test_schedule.py | 4 +- runbot/tests/test_upgrade.py | 152 ++++++----- runbot/views/build_views.xml | 1 - runbot/views/config_views.xml | 1 - runbot_builder/builder.py | 2 +- 16 files changed, 543 insertions(+), 372 deletions(-) diff --git a/runbot/container.py b/runbot/container.py index 7796e6076..78cae273b 100644 --- a/runbot/container.py +++ b/runbot/container.py @@ -14,6 +14,7 @@ import os import re import subprocess +import time import warnings # unsolved issue https://github.com/docker/docker-py/issues/2928 @@ -27,7 +28,7 @@ _logger = logging.getLogger(__name__) - +docker_stop_failures = {} class Command(): @@ -114,7 +115,6 @@ def _docker_build(build_dir, image_tag): _logger.error('Build of image %s failed with this BUILD error:', image_tag) msg = f"{e.msg}\n{''.join(l.get('stream') or '' for l in e.build_log)}" return (False, msg) - _logger.info('Dockerfile %s finished build', image_tag) return (True, None) @@ -203,6 +203,13 @@ def _docker_stop(container_name, build_dir): """Stops the container named container_name""" container_name = sanitize_container_name(container_name) _logger.info('Stopping container %s', container_name) + if container_name in docker_stop_failures: + if docker_stop_failures[container_name] + 60 * 60 < time.time(): + _logger.warning('Removing %s from docker_stop_failures', container_name) + del docker_stop_failures[container_name] + else: + _logger.warning('Skipping %s, is in failure', container_name) + return docker_client = docker.from_env() if build_dir: end_file = os.path.join(build_dir, 'end-%s' % container_name) @@ -212,11 +219,15 @@ def _docker_stop(container_name, build_dir): try: container = docker_client.containers.get(container_name) container.stop(timeout=1) + return except docker.errors.NotFound: _logger.error('Cannnot stop container %s. Container not found', container_name) except docker.errors.APIError as e: _logger.error('Cannnot stop container %s. API Error "%s"', container_name, e) + docker_stop_failures[container_name] = time.time() + + def docker_state(container_name, build_dir): container_name = sanitize_container_name(container_name) exist = os.path.exists(os.path.join(build_dir, 'exist-%s' % container_name)) diff --git a/runbot/models/build.py b/runbot/models/build.py index 3d3cf6a61..a6451d7ae 100644 --- a/runbot/models/build.py +++ b/runbot/models/build.py @@ -109,11 +109,11 @@ def _compute_commit_ids(self): def create(self, values): params = self.new(values) - match = self._find_existing(params.fingerprint) - if match: - return match - values = self._convert_to_write(params._cache) - return super().create(values) + record = self._find_existing(params.fingerprint) + if not record: + values = self._convert_to_write(params._cache) + record = super().create(values) + return record def _find_existing(self, fingerprint): return self.env['runbot.build.params'].search([('fingerprint', '=', fingerprint)], limit=1) @@ -156,10 +156,10 @@ class BuildResult(models.Model): trigger_id = fields.Many2one('runbot.trigger', related='params_id.trigger_id', store=True, index=True) # state machine - global_state = fields.Selection(make_selection(state_order), string='Status', compute='_compute_global_state', store=True, recursive=True) + global_state = fields.Selection(make_selection(state_order), string='Status', default='pending', required=True) local_state = fields.Selection(make_selection(state_order), string='Build Status', default='pending', required=True, index=True) - global_result = fields.Selection(make_selection(result_order), string='Result', compute='_compute_global_result', store=True, recursive=True) - local_result = fields.Selection(make_selection(result_order), string='Build Result') + global_result = fields.Selection(make_selection(result_order), string='Result') + local_result = fields.Selection(make_selection(result_order), string='Build Result', default='ok') triggered_result = fields.Selection(make_selection(result_order), string='Triggered Result') # triggered by db only requested_action = fields.Selection([('wake_up', 'To wake up'), ('deathrow', 'To kill')], string='Action requested', index=True) @@ -226,6 +226,7 @@ class BuildResult(models.Model): killable = fields.Boolean('Killable') database_ids = fields.One2many('runbot.database', 'build_id') + commit_export_ids = fields.One2many('runbot.commit.export', 'build_id') static_run = fields.Char('Static run URL') @@ -240,20 +241,6 @@ def _compute_log_list(self): # storing this field because it will be access trh build.log_list = ','.join({step.name for step in build.params_id.config_id.step_ids() if step._has_log()}) # TODO replace logic, add log file to list when executed (avoid 404, link log on docker start, avoid fake is_docker_step) - @api.depends('children_ids.global_state', 'local_state') - def _compute_global_state(self): - for record in self: - waiting_score = record._get_state_score('waiting') - children_ids = [child for child in record.children_ids if not child.orphan_result] - if record._get_state_score(record.local_state) > waiting_score and children_ids: # if finish, check children - children_state = record._get_youngest_state([child.global_state for child in children_ids]) - if record._get_state_score(children_state) > waiting_score: - record.global_state = record.local_state - else: - record.global_state = 'waiting' - else: - record.global_state = record.local_state - @api.depends('gc_delay', 'job_end') def _compute_gc_date(self): icp = self.env['ir.config_parameter'].sudo() @@ -285,22 +272,6 @@ def _get_youngest_state(self, states): def _get_state_score(self, result): return state_order.index(result) - @api.depends('children_ids.global_result', 'local_result', 'children_ids.orphan_result') - def _compute_global_result(self): - for record in self: - if record.local_result and record._get_result_score(record.local_result) >= record._get_result_score('ko'): - record.global_result = record.local_result - else: - children_ids = [child for child in record.children_ids if not child.orphan_result] - if children_ids: - children_result = record._get_worst_result([child.global_result for child in children_ids], max_res='ko') - if record.local_result: - record.global_result = record._get_worst_result([record.local_result, children_result]) - else: - record.global_result = children_result - else: - record.global_result = record.local_result - def _get_worst_result(self, results, max_res=False): results = [result for result in results if result] # filter Falsy values index = max([self._get_result_score(result) for result in results]) if results else 0 @@ -326,20 +297,49 @@ def copy_data(self, default=None): }) return [values] + @api.model_create_multi + def create(self, vals_list): + for values in vals_list: + if 'local_state' in values: + values['global_state'] = values['local_state'] + if 'local_result' in values: + values['global_result'] = values['local_result'] + records = super().create(vals_list) + if records.parent_id: + records.parent_id._update_global_state() + records.parent_id._update_global_result() + return records + def write(self, values): # some validation to ensure db consistency if 'local_state' in values: if values['local_state'] == 'done': - self.env['runbot.commit.export'].search([('build_id', 'in', self.ids)]).unlink() - local_result = values.get('local_result') - for build in self: - if local_result and local_result != self._get_worst_result([build.local_result, local_result]): # dont write ok on a warn/error build - if len(self) == 1: - values.pop('local_result') - else: - raise ValidationError('Local result cannot be set to a less critical level') - res = super(BuildResult, self).write(values) - return res + self.filtered(lambda b: b.local_state != 'done').commit_export_ids.unlink() + + # don't update if the value doesn't change to avoid triggering concurrent updates + def minimal_update(records, field_name): + updated = self.browse() + if field_name in values: + field_result = values.pop(field_name) + updated = records.filtered(lambda b: (b[field_name] != field_result)) + if updated: + super(BuildResult, updated).write({field_name: field_result}) + return updated + + # local result is a special case since we don't only want to avoid an update if the value didn't change, but also if the value is less than the previous one + # example: don't write 'ok' if result is 'ko' or 'warn' + if 'local_result' in values: + to_update = self.filtered(lambda b: (self._get_result_score(values['local_result']) > self._get_result_score(b.local_result))) + updated = minimal_update(to_update, 'local_result') + updated._update_global_result() + minimal_update(self, 'global_result').parent_id._update_global_result() + minimal_update(self, 'local_state')._update_global_state() + minimal_update(self, 'global_state').parent_id._update_global_state() + minimal_update(self, 'orphan_result').parent_id._update_global_result() + + if values: + super().write(values) + return True def _add_child(self, param_values, orphan=False, description=False, additionnal_commit_links=False): @@ -373,11 +373,6 @@ def result_multi(self): return 'warning' return 'ko' # ? - def update_build_end(self): - for build in self: - build.build_end = now() - if build.parent_id and build.parent_id.local_state in ('running', 'done'): - build.parent_id.update_build_end() @api.depends('params_id.version_id.name') def _compute_dest(self): @@ -451,8 +446,6 @@ def _rebuild(self, message=None): self.orphan_result = True new_build = self.create(values) - if self.parent_id: - new_build._github_status() user = request.env.user if request else self.env.user new_build._log('rebuild', 'Rebuild initiated by %s%s' % (user.name, (' :%s' % message) if message else '')) @@ -590,34 +583,21 @@ def _get_docker_name(self): self.ensure_one() return '%s_%s' % (self.dest, self.active_step.name) - def _init_pendings(self, host): - for build in self: - if build.local_state != 'pending': - raise UserError("Build %s is not pending" % build.id) - if build.host != host.name: - raise UserError("Build %s does not have correct host" % build.id) - # allocate port and schedule first job - values = { - 'port': self._find_port(), - 'job_start': now(), - 'build_start': now(), - 'job_end': False, - } - values.update(build._next_job_values()) - build.write(values) - if not build.active_step: - build._log('_schedule', 'No job in config, doing nothing') - build.local_result = 'warn' - continue - try: - build._log('_schedule', 'Init build environment with config %s ' % build.params_id.config_id.name) - os.makedirs(build._path('logs'), exist_ok=True) - except Exception: - _logger.exception('Failed initiating build %s', build.dest) - build._log('_schedule', 'Failed initiating build') - build._kill(result='ko') - continue - build._run_job() + def _init_pendings(self): + self.ensure_one() + build = self + build.port = self._find_port() + build.job_start = now() + build.build_start = now() + build.job_end = False + build._log('_schedule', 'Init build environment with config %s ' % build.params_id.config_id.name) + try: + build._log('_schedule', 'Init build environment with config %s ' % build.params_id.config_id.name) + os.makedirs(build._path('logs'), exist_ok=True) + except Exception: + _logger.exception('Failed initiating build %s', build.dest) + build._log('_schedule', 'Failed initiating build') + build._kill(result='ko') def _process_requested_actions(self): for build in self: @@ -629,12 +609,15 @@ def _process_requested_actions(self): continue if build.requested_action == 'wake_up': - if docker_state(build._get_docker_name(), build._path()) == 'RUNNING': - build.write({'requested_action': False, 'local_state': 'running'}) - build._log('wake_up', 'Waking up failed, **docker is already running**', log_type='markdown', level='SEPARATOR') + if build.local_state != 'done': + build.requested_action = False + build._log('wake_up', 'Impossible to wake-up, build is not done', log_type='markdown', level='SEPARATOR') elif not os.path.exists(build._path()): - build.write({'requested_action': False, 'local_state': 'done'}) + build.requested_action = False build._log('wake_up', 'Impossible to wake-up, **build dir does not exists anymore**', log_type='markdown', level='SEPARATOR') + elif docker_state(build._get_docker_name(), build._path()) == 'RUNNING': + build.write({'requested_action': False, 'local_state': 'running'}) + build._log('wake_up', 'Waking up failed, **docker is already running**', log_type='markdown', level='SEPARATOR') else: try: log_path = build._path('logs', 'wake_up.txt') @@ -654,7 +637,7 @@ def _process_requested_actions(self): run_step = step_ids[-1] else: run_step = self.env.ref('runbot.runbot_build_config_step_run') - run_step._run_step(build, log_path, force=True) + run_step._run_step(build, log_path, force=True)() # reload_nginx will be triggered by _run_run_odoo except Exception: _logger.exception('Failed to wake up build %s', build.dest) @@ -662,48 +645,76 @@ def _process_requested_actions(self): build.write({'requested_action': False, 'local_state': 'done'}) continue + def _update_global_result(self): + for record in self: + children = record.children_ids.filtered(lambda child: not child.orphan_result) + global_result = record.local_result + if children: + child_result = record._get_worst_result(children.mapped('global_result'), max_res='ko') + global_result = record._get_worst_result([record.local_result, child_result]) + if global_result != record.global_result: + record.global_result = global_result + if not record.parent_id: + record._github_status() # failfast + + def _update_global_state(self): + for record in self: + children = record.children_ids.filtered(lambda child: not child.orphan_result) + init_state = record.global_state + testing_children = any(child.global_state not in ('running', 'done') for child in children) + global_state = record.local_state + if testing_children: + child_state = 'waiting' + global_state = record._get_youngest_state([record.local_state, child_state]) + + if global_state != record.global_state: + record.global_state = global_state + + ending_build = init_state not in ('done', 'running') and record.global_state in ('done', 'running') + + if ending_build: + if not record.local_result: # Set 'ok' result if no result set (no tests job on build) + record.local_result = 'ok' + record.build_end = now() + if not record.parent_id: + record._github_status() + def _schedule(self): """schedule the build""" icp = self.env['ir.config_parameter'].sudo() - hosts_by_name = {h.name: h for h in self.env['runbot.host'].search([('name', 'in', self.mapped('host'))])} - hosts_by_build = {b.id: hosts_by_name[b.host] for b in self} - for build in self: - if build.local_state not in ['testing', 'running']: - raise UserError("Build %s is not testing/running: %s" % (build.id, build.local_state)) - if build.local_state == 'testing': - # failfast in case of docker error (triggered in database) - if build.triggered_result and not build.active_step.ignore_triggered_result: - worst_result = self._get_worst_result([build.triggered_result, build.local_result]) - if worst_result != build.local_result: - build.local_result = build.triggered_result - build._github_status() # failfast - # check if current job is finished + self.ensure_one() + build = self + if build.local_state not in ['testing', 'running', 'pending']: + return False + # check if current job is finished + if build.local_state == 'pending': + build._init_pendings() + else: _docker_state = docker_state(build._get_docker_name(), build._path()) if _docker_state == 'RUNNING': timeout = min(build.active_step.cpu_limit, int(icp.get_param('runbot.runbot_timeout', default=10000))) if build.local_state != 'running' and build.job_time > timeout: build._log('_schedule', '%s time exceeded (%ss)' % (build.active_step.name if build.active_step else "?", build.job_time)) build._kill(result='killed') - continue + return False elif _docker_state in ('UNKNOWN', 'GHOST') and (build.local_state == 'running' or build.active_step._is_docker_step()): # todo replace with docker_start docker_time = time.time() - dt2time(build.docker_start or build.job_start) if docker_time < 5: - continue + return False elif docker_time < 60: _logger.info('container "%s" seems too take a while to start :%s' % (build.job_time, build._get_docker_name())) - continue + return False else: build._log('_schedule', 'Docker with state %s not started after 60 seconds, skipping' % _docker_state, level='ERROR') - if hosts_by_build[build.id]._fetch_local_logs(build_ids=build.ids): - continue # avoid to make results with remaining logs + if self.env['runbot.host']._fetch_local_logs(build_ids=build.ids): + return True # avoid to make results with remaining logs # No job running, make result and select next job - build_values = { - 'job_end': now(), - 'docker_start': False, - } + + build.job_end = now() + build.docker_start = False # make result of previous job try: - results = build.active_step._make_results(build) + build.active_step._make_results(build) except Exception as e: if isinstance(e, RunbotException): message = e.args[0][:300000] @@ -711,50 +722,70 @@ def _schedule(self): message = 'An error occured while computing results of %s:\n %s' % (build.job, str(e).replace('\\n', '\n').replace("\\'", "'")[:10000]) _logger.exception(message) build._log('_make_results', message, level='ERROR') - results = {'local_result': 'ko'} - - build_values.update(results) + build.local_result = 'ko' # compute statistics before starting next job build.active_step._make_stats(build) - build.active_step.log_end(build) - build_values.update(build._next_job_values()) # find next active_step or set to done + step_ids = self.params_id.config_id.step_ids() + if not step_ids: # no job to do, build is done + self.active_step = False + self.local_state = 'done' + build._log('_schedule', 'No job in config, doing nothing') + build.local_result = 'warn' + if not self.active_step and self.local_state != 'pending': + # means that a step has been run manually without using config (wakeup) + build.active_step = False + build.local_state = 'done' - ending_build = build.local_state not in ('done', 'running') and build_values.get('local_state') in ('done', 'running') - if ending_build: - build.update_build_end() + if not self.active_step: + next_index = 0 + else: + if self.active_step not in step_ids: + self._log('run', 'Config was modified and current step does not exists anymore, skipping.', level='ERROR') + self.active_step = False + self.local_state = 'done' + self.local_result = 'ko' + return False + next_index = step_ids.index(self.active_step) + 1 - build.write(build_values) - if ending_build: - if not build.local_result: # Set 'ok' result if no result set (no tests job on build) - build.local_result = 'ok' - build._logger("No result set, setting ok by default") - build._github_status() - build._run_job() + while True: + if next_index >= len(step_ids): # final job, build is done + self.active_step = False + self.local_state = 'done' + return False + new_step = step_ids[next_index] # job to do, state is job_state (testing or running) + if new_step.domain_filter and not self.filtered_domain(safe_eval(new_step.domain_filter)): + self._log('run', '**Skipping** step ~~%s~~ from config **%s**' % (new_step.name, self.params_id.config_id.name), log_type='markdown', level='SEPARATOR') + next_index += 1 + continue + break + build.active_step = new_step.id + build.local_state = new_step._step_state() + return build._run_job() def _run_job(self): - # run job - for build in self: - if build.local_state != 'done': - build._logger('running %s', build.active_step.name) - os.makedirs(build._path('logs'), exist_ok=True) - os.makedirs(build._path('datadir'), exist_ok=True) - try: - build.active_step._run(build) # run should be on build? - except TransactionRollbackError: - raise - except Exception as e: - if isinstance(e, RunbotException): - message = e.args[0] - else: - message = '%s failed running step %s:\n %s' % (build.dest, build.job, str(e).replace('\\n', '\n').replace("\\'", "'")) - _logger.exception(message) - build._log("run", message, level='ERROR') - build._kill(result='ko') + self.ensure_one() + build = self + if build.local_state != 'done': + build._logger('running %s', build.active_step.name) + os.makedirs(build._path('logs'), exist_ok=True) + os.makedirs(build._path('datadir'), exist_ok=True) + try: + return build.active_step._run(build) # run should be on build? + except TransactionRollbackError: + raise + except Exception as e: + if isinstance(e, RunbotException): + message = e.args[0] + else: + message = '%s failed running step %s:\n %s' % (build.dest, build.job, str(e).replace('\\n', '\n').replace("\\'", "'")) + _logger.exception(message) + build._log("run", message, level='ERROR') + build._kill(result='ko') def _docker_run(self, cmd=None, ro_volumes=None, **kwargs): self.ensure_one() @@ -926,7 +957,6 @@ def _kill(self, result=None): v['local_result'] = result build.write(v) self.env.cr.commit() - build._github_status() self.invalidate_cache() def _ask_kill(self, lock=True, message=None): @@ -1024,8 +1054,9 @@ def _cmd(self, python_params=None, py_version=None, local_only=True, sub_command elif grep(config_path, "--xmlrpc-interface"): command.add_config_tuple("xmlrpc_interface", "127.0.0.1") + log_db = self.env['ir.config_parameter'].get_param('runbot.logdb_name') if grep(config_path, "log-db"): - command.add_config_tuple("log_db", "runbot_logs") + command.add_config_tuple("log_db", log_db) if grep(config_path, 'log-db-level'): command.add_config_tuple("log_db_level", '25') @@ -1051,35 +1082,7 @@ def _cmd_check(self, cmd): 'build_id': self.id }) - def _next_job_values(self): - self.ensure_one() - step_ids = self.params_id.config_id.step_ids() - if not step_ids: # no job to do, build is done - return {'active_step': False, 'local_state': 'done'} - - if not self.active_step and self.local_state != 'pending': - # means that a step has been run manually without using config - return {'active_step': False, 'local_state': 'done'} - - if not self.active_step: - next_index = 0 - else: - if self.active_step not in step_ids: - self._log('run', 'Config was modified and current step does not exists anymore, skipping.', level='ERROR') - return {'active_step': False, 'local_state': 'done', 'local_result': self._get_worst_result([self.local_result, 'ko'])} - next_index = step_ids.index(self.active_step) + 1 - - while True: - if next_index >= len(step_ids): # final job, build is done - return {'active_step': False, 'local_state': 'done'} - new_step = step_ids[next_index] # job to do, state is job_state (testing or running) - if new_step.domain_filter and not self.filtered_domain(safe_eval(new_step.domain_filter)): - - self._log('run', '**Skipping** step ~~%s~~ from config **%s**' % (new_step.name, self.params_id.config_id.name), log_type='markdown', level='SEPARATOR') - next_index += 1 - continue - break - return {'active_step': new_step.id, 'local_state': new_step._step_state()} + def _get_py_version(self): """return the python name to use from build batch""" diff --git a/runbot/models/build_config.py b/runbot/models/build_config.py index f87c9f8b9..2e9d2328c 100644 --- a/runbot/models/build_config.py +++ b/runbot/models/build_config.py @@ -166,7 +166,6 @@ class ConfigStep(models.Model): # python python_code = fields.Text('Python code', tracking=True, default=PYTHON_DEFAULT) python_result_code = fields.Text('Python code for result', tracking=True, default=PYTHON_DEFAULT) - ignore_triggered_result = fields.Boolean('Ignore error triggered in logs', tracking=True, default=False) running_job = fields.Boolean('Job final state is running', default=False, help="Docker won't be killed if checked") # create_build create_config_ids = fields.Many2many('runbot.build.config', 'runbot_build_config_step_ids_create_config_ids_rel', string='New Build Configs', tracking=True, index=True) @@ -275,14 +274,16 @@ def _run(self, build): url = f"{log_url}/runbot/static/build/{build.dest}/logs/{self.name}.txt" log_link = f'[@icon-file-text]({url})' build._log('run', 'Starting step **%s** from config **%s** %s' % (self.name, build.params_id.config_id.name, log_link), log_type='markdown', level='SEPARATOR') - self._run_step(build, log_path) + return self._run_step(build, log_path) def _run_step(self, build, log_path, **kwargs): build.log_counter = self.env['ir.config_parameter'].sudo().get_param('runbot.runbot_maxlogs', 100) run_method = getattr(self, '_run_%s' % self.job_type) docker_params = run_method(build, log_path, **kwargs) if docker_params: - build._docker_run(**docker_params) + def start_docker(): + build._docker_run(**docker_params) + return start_docker def _run_create_build(self, build, log_path): count = 0 @@ -909,23 +910,20 @@ def _coverage_params(self, build, modules_to_install): return ['--omit', ','.join(pattern_to_omit)] def _make_results(self, build): - build_values = {} log_time = self._get_log_last_write(build) if log_time: - build_values['job_end'] = log_time + build.job_end = log_time if self.job_type == 'python' and self.python_result_code and self.python_result_code != PYTHON_DEFAULT: - build_values.update(self._make_python_results(build)) + build.write(self._make_python_results(build)) elif self.job_type in ['install_odoo', 'python']: if self.coverage: - build_values.update(self._make_coverage_results(build)) + build.write(self._make_coverage_results(build)) if self.test_enable or self.test_tags: - build_values.update(self._make_tests_results(build)) + build.write(self._make_tests_results(build)) elif self.job_type == 'test_upgrade': - build_values.update(self._make_upgrade_results(build)) + build.write(self._make_upgrade_results(build)) elif self.job_type == 'restore': - build_values.update(self._make_restore_results(build)) - - return build_values + build.write(self._make_restore_results(build)) def _make_python_results(self, build): eval_ctx = self.make_python_ctx(build) diff --git a/runbot/models/event.py b/runbot/models/event.py index a771ce47b..d4c18233a 100644 --- a/runbot/models/event.py +++ b/runbot/models/event.py @@ -36,10 +36,11 @@ def create(self, vals_list): build_logs = logs_by_build_id[build.id] for ir_log in build_logs: ir_log['active_step_id'] = build.active_step.id - if ir_log['level'].upper() == 'WARNING': - build.triggered_result = 'warn' - elif ir_log['level'].upper() == 'ERROR': - build.triggered_result = 'ko' + if build.local_state != 'running': + if ir_log['level'].upper() == 'WARNING': + build.local_result = 'warn' + elif ir_log['level'].upper() == 'ERROR': + build.local_result = 'ko' return super().create(vals_list) def _markdown(self): diff --git a/runbot/models/host.py b/runbot/models/host.py index cd84e6ea3..19e72a738 100644 --- a/runbot/models/host.py +++ b/runbot/models/host.py @@ -1,5 +1,6 @@ import logging import getpass +import time from collections import defaultdict @@ -112,9 +113,11 @@ def _docker_build(self): self.clear_caches() # needed to ensure that content is updated on all hosts for dockerfile in self.env['runbot.dockerfile'].search([('to_build', '=', True)]): self._docker_build_dockerfile(dockerfile, static_path) + _logger.info('Done...') def _docker_build_dockerfile(self, dockerfile, workdir): - _logger.info('Building %s, %s', dockerfile.name, hash(str(dockerfile.dockerfile))) + start = time.time() + # _logger.info('Building %s, %s', dockerfile.name, hash(str(dockerfile.dockerfile))) docker_build_path = os.path.join(workdir, 'docker', dockerfile.image_tag) os.makedirs(docker_build_path, exist_ok=True) @@ -137,6 +140,10 @@ def _docker_build_dockerfile(self, dockerfile, workdir): dockerfile.to_build = False dockerfile.message_post(body=f'Build failure:\n{msg}') self.env['runbot.runbot'].warning(f'Dockerfile build "{dockerfile.image_tag}" failed on host {self.name}') + else: + duration = time.time() - start + if duration > 1: + _logger.info('Dockerfile %s finished build in %s', dockerfile.image_tag, duration) def _get_work_path(self): return os.path.abspath(os.path.join(os.path.dirname(__file__), '../static')) @@ -244,3 +251,10 @@ def process_logs(self, build_ids=None): logs_db_name = self.env['ir.config_parameter'].get_param('runbot.logdb_name') with local_pg_cursor(logs_db_name) as local_cr: local_cr.execute("DELETE FROM ir_logging WHERE id in %s", [tuple(local_log_ids)]) + + def get_build_domain(self, domain=None): + domain = domain or [] + return [('host', '=', self.name)] + domain + + def get_builds(self, domain, order=None): + return self.env['runbot.build'].search(self.get_build_domain(domain), order=order) diff --git a/runbot/models/runbot.py b/runbot/models/runbot.py index 679dfc1ff..26999d36b 100644 --- a/runbot/models/runbot.py +++ b/runbot/models/runbot.py @@ -39,78 +39,79 @@ def _root(self): def _scheduler(self, host): self._gc_testing(host) self._commit() - for build in self._get_builds_with_requested_actions(host): - build = build.browse(build.id) # remove preftech ids, manage build one by one + processed = 0 + for build in host.get_builds([('requested_action', 'in', ['wake_up', 'deathrow'])]): + processed += 1 build._process_requested_actions() self._commit() host.process_logs() self._commit() - for build in self._get_builds_to_schedule(host): + #for build in host.get_builds([('global_state', 'not in', ('running', 'done'))]).sorted(lambda b: -b.id): + # # processed += 1 # not sure if we should update + # build = build.browse(build.id) # remove preftech ids, manage build one by one + + # self._commit() + for build in host.get_builds([('local_state', 'in', ['testing', 'running'])]) | self._get_builds_to_init(host): build = build.browse(build.id) # remove preftech ids, manage build one by one - build._schedule() + result = build._schedule() + if result: + processed += 1 self._commit() - self._assign_pending_builds(host, host.nb_worker, [('build_type', '!=', 'scheduled')]) + if callable(result): + result() # start docker + processed += self._assign_pending_builds(host, host.nb_worker, [('build_type', '!=', 'scheduled')]) self._commit() - self._assign_pending_builds(host, host.nb_worker - 1 or host.nb_worker) + processed += self._assign_pending_builds(host, host.nb_worker - 1 or host.nb_worker) self._commit() - self._assign_pending_builds(host, host.nb_worker and host.nb_worker + 1, [('build_type', '=', 'priority')]) + processed += self._assign_pending_builds(host, host.nb_worker and host.nb_worker + 1, [('build_type', '=', 'priority')]) self._commit() - for build in self._get_builds_to_init(host): - build = build.browse(build.id) # remove preftech ids, manage build one by one - build._init_pendings(host) - self._commit() self._gc_running(host) self._commit() self._reload_nginx() - - def build_domain_host(self, host, domain=None): - domain = domain or [] - return [('host', '=', host.name)] + domain - - def _get_builds_with_requested_actions(self, host): - return self.env['runbot.build'].search(self.build_domain_host(host, [('requested_action', 'in', ['wake_up', 'deathrow'])])) - - def _get_builds_to_schedule(self, host): - return self.env['runbot.build'].search(self.build_domain_host(host, [('local_state', 'in', ['testing', 'running'])])) + self._commit() + return processed def _assign_pending_builds(self, host, nb_worker, domain=None): if host.assigned_only or nb_worker <= 0: - return - domain_host = self.build_domain_host(host) - reserved_slots = self.env['runbot.build'].search_count(domain_host + [('local_state', 'in', ('testing', 'pending'))]) + return 0 + reserved_slots = len(host.get_builds([('local_state', 'in', ('testing', 'pending'))])) assignable_slots = (nb_worker - reserved_slots) if assignable_slots > 0: allocated = self._allocate_builds(host, assignable_slots, domain) if allocated: _logger.info('Builds %s where allocated to runbot', allocated) + return len(allocated) + return 0 def _get_builds_to_init(self, host): - domain_host = self.build_domain_host(host) - used_slots = self.env['runbot.build'].search_count(domain_host + [('local_state', '=', 'testing')]) + domain_host = host.get_build_domain() + used_slots = len(host.get_builds([('local_state', '=', 'testing')])) available_slots = host.nb_worker - used_slots - if available_slots <= 0: - return self.env['runbot.build'] - return self.env['runbot.build'].search(domain_host + [('local_state', '=', 'pending')], limit=available_slots) + build_to_init = self.env['runbot.build'] + if available_slots > 0: + build_to_init |= self.env['runbot.build'].search(domain_host + [('local_state', '=', 'pending')], limit=available_slots) + if available_slots + 1 > 0: + build_to_init |= self.env['runbot.build'].search(domain_host + [('local_state', '=', 'pending'), ('build_type', '=', 'priority')], limit=1) + return build_to_init def _gc_running(self, host): running_max = host.get_running_max() - domain_host = self.build_domain_host(host) + cannot_be_killed_ids = host.get_builds([('keep_running', '=', True)]).ids Build = self.env['runbot.build'] - cannot_be_killed_ids = Build.search(domain_host + [('keep_running', '=', True)]).ids sticky_bundles = self.env['runbot.bundle'].search([('sticky', '=', True), ('project_id.keep_sticky_running', '=', True)]) cannot_be_killed_ids += [ build.id for build in sticky_bundles.mapped('last_batchs.slot_ids.build_id') if build.host == host.name ][:running_max] - build_ids = Build.search(domain_host + [('local_state', '=', 'running'), ('id', 'not in', cannot_be_killed_ids)], order='job_start desc').ids + build_ids = host.get_builds([('local_state', '=', 'running'), ('id', 'not in', cannot_be_killed_ids)], order='job_start desc').ids Build.browse(build_ids)[running_max:]._kill() def _gc_testing(self, host): """garbage collect builds that could be killed""" # decide if we need room Build = self.env['runbot.build'] - domain_host = self.build_domain_host(host) + domain_host = host.get_build_domain() testing_builds = Build.search(domain_host + [('local_state', 'in', ['testing', 'pending']), ('requested_action', '!=', 'deathrow')]) used_slots = len(testing_builds) available_slots = host.nb_worker - used_slots @@ -277,14 +278,13 @@ def _fetch_loop_turn(self, host, pull_info_failures, default_sleep=1): _logger.warning('Removing %s from pull_info_failures', pr_number) del pull_info_failures[pr_number] - return manager.get('sleep', default_sleep) - def _scheduler_loop_turn(self, host, default_sleep=5): - _logger.info('Scheduling...') + def _scheduler_loop_turn(self, host, sleep=5): with self.manage_host_exception(host) as manager: - self._scheduler(host) - return manager.get('sleep', default_sleep) + if self._scheduler(host): + sleep = 0.1 + return manager.get('sleep', sleep) @contextmanager def manage_host_exception(self, host): diff --git a/runbot/tests/common.py b/runbot/tests/common.py index 67b86c5ae..57324dea1 100644 --- a/runbot/tests/common.py +++ b/runbot/tests/common.py @@ -181,7 +181,6 @@ def setUp(self): self.start_patcher('docker_stop', 'odoo.addons.runbot.container._docker_stop') self.start_patcher('docker_get_gateway_ip', 'odoo.addons.runbot.models.build_config.docker_get_gateway_ip', None) - self.start_patcher('cr_commit', 'odoo.sql_db.Cursor.commit', None) self.start_patcher('repo_commit', 'odoo.addons.runbot.models.runbot.Runbot._commit', None) self.start_patcher('_local_cleanup_patcher', 'odoo.addons.runbot.models.build.BuildResult._local_cleanup') self.start_patcher('_local_pg_dropdb_patcher', 'odoo.addons.runbot.models.build.BuildResult._local_pg_dropdb') @@ -194,6 +193,11 @@ def setUp(self): self.start_patcher('_get_py_version', 'odoo.addons.runbot.models.build.BuildResult._get_py_version', 3) + def no_commit(*_args, **_kwargs): + _logger.info('Skipping commit') + + self.patch(self.env.cr, 'commit', no_commit) + def start_patcher(self, patcher_name, patcher_path, return_value=DEFAULT, side_effect=DEFAULT, new=DEFAULT): diff --git a/runbot/tests/test_build.py b/runbot/tests/test_build.py index d1fa191ad..cab7554f8 100644 --- a/runbot/tests/test_build.py +++ b/runbot/tests/test_build.py @@ -170,8 +170,10 @@ def test_base_fields(self): # test a bulk write, that one cannot change from 'ko' to 'ok' builds = self.Build.browse([build.id, other.id]) - with self.assertRaises(ValidationError): - builds.write({'local_result': 'ok'}) + builds.write({'local_result': 'warn'}) + self.assertEqual(build.local_result, 'warn') + self.assertEqual(other.local_result, 'ko') + def test_markdown_description(self): build = self.Build.create({ @@ -331,6 +333,11 @@ def test_children(self): build1 = self.Build.create({ 'params_id': self.server_params.id, }) + self.assertEqual('pending', build1.global_state) + + build1.local_state = 'testing' + self.assertEqual('testing', build1.global_state) + build1_1 = self.Build.create({ 'params_id': self.server_params.id, 'parent_id': build1.id, @@ -339,6 +346,15 @@ def test_children(self): 'params_id': self.server_params.id, 'parent_id': build1.id, }) + self.assertEqual('testing', build1.global_state) + self.assertEqual('pending', build1_1.global_state) + self.assertEqual('pending', build1_2.global_state) + + build1_1.local_state = 'testing' + self.assertEqual('testing', build1.global_state) + self.assertEqual('testing', build1_1.global_state) + self.assertEqual('pending', build1_2.global_state) + build1_1_1 = self.Build.create({ 'params_id': self.server_params.id, 'parent_id': build1_1.id, @@ -348,60 +364,130 @@ def test_children(self): 'parent_id': build1_1.id, }) - def assert_state(global_state, build): - self.assertEqual(build.global_state, global_state) + self.assertEqual('testing', build1.global_state) + self.assertEqual('testing', build1_1.global_state) + self.assertEqual('pending', build1_2.global_state) + self.assertEqual('pending', build1_1_1.global_state) + self.assertEqual('pending', build1_1_2.global_state) - assert_state('pending', build1) - assert_state('pending', build1_1) - assert_state('pending', build1_2) - assert_state('pending', build1_1_1) - assert_state('pending', build1_1_2) + with self.assertQueries(['''UPDATE "runbot_build" SET "global_state"=%s,"local_state"=%s,"write_date"=%s,"write_uid"=%s WHERE id IN %s''']): + build1_2.local_state = "testing" + + self.assertEqual('testing', build1.global_state) + self.assertEqual('testing', build1_2.global_state) + + with self.assertQueries([]): # no change should be triggered + build1_2.local_state = "testing" + + with self.assertQueries(['''UPDATE "runbot_build" SET "global_state"=%s,"local_state"=%s,"write_date"=%s,"write_uid"=%s WHERE id IN %s''']): + build1.local_state = 'done' + build1.flush() + + self.assertEqual('waiting', build1.global_state) + self.assertEqual('testing', build1_1.global_state) + + with self.assertQueries([]): + build1.local_state = 'done' # write the same value, no update should be triggered + build1.flush() - build1.local_state = 'testing' - build1_1.local_state = 'testing' - build1.local_state = 'done' build1_1.local_state = 'done' - assert_state('waiting', build1) - assert_state('waiting', build1_1) - assert_state('pending', build1_2) - assert_state('pending', build1_1_1) - assert_state('pending', build1_1_2) + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('testing', build1_2.global_state) + self.assertEqual('pending', build1_1_1.global_state) + self.assertEqual('pending', build1_1_2.global_state) build1_1_1.local_state = 'testing' - assert_state('waiting', build1) - assert_state('waiting', build1_1) - assert_state('pending', build1_2) - assert_state('testing', build1_1_1) - assert_state('pending', build1_1_2) + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('testing', build1_2.global_state) + self.assertEqual('testing', build1_1_1.global_state) + self.assertEqual('pending', build1_1_2.global_state) - build1_2.local_state = 'testing' + with self.assertQueries([]): + build1_2.local_state = 'testing' - assert_state('waiting', build1) - assert_state('waiting', build1_1) - assert_state('testing', build1_2) - assert_state('testing', build1_1_1) - assert_state('pending', build1_1_2) + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('testing', build1_2.global_state) + self.assertEqual('testing', build1_1_1.global_state) + self.assertEqual('pending', build1_1_2.global_state) - build1_2.local_state = 'testing' # writing same state a second time + build1_2.local_state = 'done' + build1_1_1.local_state = 'done' + build1_1_2.local_state = 'testing' - assert_state('waiting', build1) - assert_state('waiting', build1_1) - assert_state('testing', build1_2) - assert_state('testing', build1_1_1) - assert_state('pending', build1_1_2) + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('done', build1_2.global_state) + self.assertEqual('done', build1_1_1.global_state) + self.assertEqual('testing', build1_1_2.global_state) build1_1_2.local_state = 'done' - build1_1_1.local_state = 'done' - build1_2.local_state = 'done' - assert_state('done', build1) - assert_state('done', build1_1) - assert_state('done', build1_2) - assert_state('done', build1_1_1) - assert_state('done', build1_1_2) + self.assertEqual('done', build1.global_state) + self.assertEqual('done', build1_1.global_state) + self.assertEqual('done', build1_2.global_state) + self.assertEqual('done', build1_1_1.global_state) + self.assertEqual('done', build1_1_2.global_state) + + def test_rebuild_sub_sub_build(self): + build1 = self.Build.create({ + 'params_id': self.server_params.id, + }) + build1.local_state = 'testing' + build1_1 = self.Build.create({ + 'params_id': self.server_params.id, + 'parent_id': build1.id, + }) + build1_1.local_state = 'testing' + build1.local_state = 'done' + build1_1_1 = self.Build.create({ + 'params_id': self.server_params.id, + 'parent_id': build1_1.id, + }) + build1_1_1.local_state = 'testing' + build1_1.local_state = 'done' + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('testing', build1_1_1.global_state) + build1_1_1.local_result = 'ko' + build1_1_1.local_state = 'done' + self.assertEqual('done', build1.global_state) + self.assertEqual('done', build1_1.global_state) + self.assertEqual('done', build1_1_1.global_state) + self.assertEqual('ko', build1.global_result) + self.assertEqual('ko', build1_1.global_result) + self.assertEqual('ko', build1_1_1.global_result) + + rebuild1_1_1 = self.Build.create({ # this is a rebuild + 'params_id': self.server_params.id, + 'parent_id': build1_1.id, + }) + build1_1_1.orphan_result = True + + self.assertEqual('ok', build1.global_result) + self.assertEqual('ok', build1_1.global_result) + self.assertEqual('ko', build1_1_1.global_result) + self.assertEqual('waiting', build1.global_state) + self.assertEqual('waiting', build1_1.global_state) + self.assertEqual('done', build1_1_1.global_state) + self.assertEqual('pending', rebuild1_1_1.global_state) + + rebuild1_1_1.local_result = 'ok' + rebuild1_1_1.local_state = 'done' + + self.assertEqual('ok', build1.global_result) + self.assertEqual('ok', build1_1.global_result) + self.assertEqual('ko', build1_1_1.global_result) + self.assertEqual(False, rebuild1_1_1.global_result) + self.assertEqual('done', build1.global_state) + self.assertEqual('done', build1_1.global_state) + self.assertEqual('done', build1_1_1.global_state) + self.assertEqual('done', rebuild1_1_1.global_state) class TestGc(RunbotCaseMinimalSetup): @@ -446,6 +532,7 @@ def test_repo_gc_testing(self): build_a.write({'local_state': 'testing', 'host': host.name}) build_b.write({'local_state': 'testing', 'host': 'runbot_yyy'}) + # no room needed, verify that nobody got killed self.Runbot._gc_testing(host) self.assertFalse(build_a.requested_action) diff --git a/runbot/tests/test_build_config_step.py b/runbot/tests/test_build_config_step.py index 1053a0987..524116c04 100644 --- a/runbot/tests/test_build_config_step.py +++ b/runbot/tests/test_build_config_step.py @@ -214,7 +214,6 @@ def setUp(self): def test_config_step_create_results(self): """ Test child builds are taken into account""" - self.config_step._run_create_build(self.parent_build, '/tmp/essai') self.assertEqual(len(self.parent_build.children_ids), 2, 'Two sub-builds should have been generated') @@ -222,8 +221,10 @@ def test_config_step_create_results(self): for child_build in self.parent_build.children_ids: self.assertFalse(child_build.orphan_result) child_build.local_result = 'ko' + self.assertEqual(child_build.global_result, 'ko') + self.assertEqual(self.parent_build.global_result, 'ko') def test_config_step_create(self): @@ -236,6 +237,7 @@ def test_config_step_create(self): for child_build in self.parent_build.children_ids: self.assertTrue(child_build.orphan_result, 'An orphan result config step should mark the build as orphan_result') child_build.local_result = 'ko' + # child_build._update_:globals() self.assertEqual(self.parent_build.global_result, 'ok') @@ -455,19 +457,19 @@ def docker_run(cmd, log_path, *args, **kwargs): self.patchers['docker_run'].side_effect = docker_run - config_step._run_step(self.parent_build, 'dev/null/logpath') + config_step._run_step(self.parent_build, 'dev/null/logpath')() assert_db_name = 'custom_build' parent_build_params = self.parent_build.params_id.copy({'config_data': {'db_name': 'custom_build'}}) parent_build = self.parent_build.copy({'params_id': parent_build_params.id}) - config_step._run_step(parent_build, 'dev/null/logpath') + config_step._run_step(parent_build, 'dev/null/logpath')() config_step = self.ConfigStep.create({ 'name': 'run_test', 'job_type': 'run_odoo', 'custom_db_name': 'custom', }) - config_step._run_step(parent_build, 'dev/null/logpath') + config_step._run_step(parent_build, 'dev/null/logpath')() self.assertEqual(call_count, 3) @@ -489,7 +491,7 @@ def docker_run(cmd, *args, **kwargs): self.assertIn('-d test_database', run_cmd) self.patchers['docker_run'].side_effect = docker_run - config_step._run_step(self.parent_build, 'dev/null/logpath') + config_step._run_step(self.parent_build, 'dev/null/logpath')() self.patchers['docker_run'].assert_called_once() db = self.env['runbot.database'].search([('name', '=', 'test_database')]) self.assertEqual(db.build_id, self.parent_build) @@ -525,7 +527,7 @@ def docker_run(cmd, log_path, *args, **kwargs): call_count += 1 self.patchers['docker_run'].side_effect = docker_run - config_step._run_step(self.parent_build, 'dev/null/logpath') + config_step._run_step(self.parent_build, 'dev/null/logpath')() self.assertEqual(call_count, 1) @@ -564,10 +566,14 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): }) logs = [] with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'ok'}) + config_step._make_results(build) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') self.assertEqual(logs, [('INFO', 'Getting results for build %s' % build.dest)]) + self.assertEqual(build.local_result, 'ok') # no shutdown + build = self.Build.create({ + 'params_id': self.base_params.id, + }) logs = [] file_content = """ Loading stuff @@ -575,26 +581,34 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): Some post install stuff """ with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'ko'}) + config_step._make_results(build) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') + self.assertEqual(build.local_result, 'ko') self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest), ('ERROR', 'No "Initiating shutdown" found in logs, maybe because of cpu limit.') ]) # no loaded + build = self.Build.create({ + 'params_id': self.base_params.id, + }) logs = [] file_content = """ Loading stuff """ with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'ko'}) + config_step._make_results(build) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') + self.assertEqual(build.local_result, 'ko') self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest), ('ERROR', 'Modules loaded not found in logs') ]) # traceback + build = self.Build.create({ + 'params_id': self.base_params.id, + }) logs = [] file_content = """ Loading stuff @@ -607,14 +621,18 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): Initiating shutdown """ with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'ko'}) + config_step._make_results(build) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') + self.assertEqual(build.local_result, 'ko') self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest), ('ERROR', 'Error or traceback found in logs') ]) # warning in logs + build = self.Build.create({ + 'params_id': self.base_params.id, + }) logs = [] file_content = """ Loading stuff @@ -624,8 +642,9 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): Initiating shutdown """ with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'warn'}) + config_step._make_results(build) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') + self.assertEqual(build.local_result, 'warn') self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest), ('WARNING', 'Warning found in logs') @@ -634,15 +653,18 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): # no log file logs = [] self.patchers['isfile'].return_value = False - result = config_step._make_results(build) + config_step._make_results(build) - self.assertEqual(result, {'local_result': 'ko'}) + self.assertEqual(build.local_result, 'ko') self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest), ('ERROR', 'Log file not found at the end of test job') ]) # no error but build was already in warn + build = self.Build.create({ + 'params_id': self.base_params.id, + }) logs = [] file_content = """ Loading stuff @@ -653,11 +675,12 @@ def _log(func, message, level='INFO', log_type='runbot', path='runbot'): self.patchers['isfile'].return_value = True build.local_result = 'warn' with patch('builtins.open', mock_open(read_data=file_content)): - result = config_step._make_results(build) + config_step._make_results(build) self.assertEqual(logs, [ ('INFO', 'Getting results for build %s' % build.dest) ]) - self.assertEqual(result, {'job_end': '1970-01-01 02:00:00', 'local_result': 'warn'}) + self.assertEqual(str(build.job_end), '1970-01-01 02:00:00') + self.assertEqual(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): @@ -672,18 +695,18 @@ def test_make_python_result(self, mock_make_tests_results): }) build.local_state = 'testing' self.patchers['isfile'].return_value = False - result = config_step._make_results(build) - self.assertEqual(result, {'local_result': 'ok'}) + config_step._make_results(build) + self.assertEqual(build.local_result, 'ok') # invalid result code (no return_value set) config_step.python_result_code = """a = 2*5\nr = {'a': 'ok'}\nreturn_value = 'ko'""" with self.assertRaises(RunbotException): - result = config_step._make_results(build) + config_step._make_results(build) # no result defined config_step.python_result_code = "" - mock_make_tests_results.return_value = {'local_result': 'warning'} - result = config_step._make_results(build) - self.assertEqual(result, {'local_result': 'warning'}) + mock_make_tests_results.return_value = {'local_result': 'warn'} + config_step._make_results(build) + self.assertEqual(build.local_result, 'warn') # TODO add generic test to copy_paste _run_* in a python step diff --git a/runbot/tests/test_build_error.py b/runbot/tests/test_build_error.py index c7cca2579..0d616ab6e 100644 --- a/runbot/tests/test_build_error.py +++ b/runbot/tests/test_build_error.py @@ -33,8 +33,10 @@ def setUp(self): def test_build_scan(self): IrLog = self.env['ir.logging'] - ko_build = self.create_test_build({'local_result': 'ko'}) - ok_build = self.create_test_build({'local_result': 'ok'}) + ko_build = self.create_test_build({'local_result': 'ok', 'local_state': 'testing'}) + ok_build = self.create_test_build({'local_result': 'ok', 'local_state': 'running'}) + + error_team = self.BuildErrorTeam.create({ 'name': 'test-error-team', @@ -56,6 +58,10 @@ def test_build_scan(self): IrLog.create(log) log.update({'build_id': ok_build.id}) IrLog.create(log) + + self.assertEqual(ko_build.local_result, 'ko', 'Testing build should have gone ko after error log') + self.assertEqual(ok_build.local_result, 'ok', 'Running build should not have gone ko after error log') + ko_build._parse_logs() ok_build._parse_logs() build_error = self.BuildError.search([('build_ids', 'in', [ko_build.id])]) diff --git a/runbot/tests/test_host.py b/runbot/tests/test_host.py index fb839910a..bb47fc59d 100644 --- a/runbot/tests/test_host.py +++ b/runbot/tests/test_host.py @@ -88,7 +88,7 @@ def test_build_logs(self): ]), 1, ) - self.assertEqual(build.triggered_result, 'warn', 'A warning log should sets the build in warn') + self.assertEqual(build.local_result, 'warn', 'A warning log should sets the build in warn') # now check that error logs sets the build in ko logs = fetch_local_logs_return_value(nb_logs=1, build_dest=build.dest, level='ERROR') @@ -103,7 +103,7 @@ def test_build_logs(self): ]), 1, ) - self.assertEqual(build.triggered_result, 'ko', 'An error log should sets the build in ko') + self.assertEqual(build.local_result, 'ko', 'An error log should sets the build in ko') build.log_counter = 10 # Test log limit diff --git a/runbot/tests/test_schedule.py b/runbot/tests/test_schedule.py index ba9dcddb5..0e47f6d7b 100644 --- a/runbot/tests/test_schedule.py +++ b/runbot/tests/test_schedule.py @@ -23,6 +23,7 @@ def test_schedule_mark_done(self, mock_docker_state, mock_getmtime): build = self.Build.create({ 'local_state': 'testing', + 'global_state': 'testing', 'port': '1234', 'host': host.name, 'job_start': datetime.datetime.now(), @@ -33,9 +34,10 @@ def test_schedule_mark_done(self, mock_docker_state, mock_getmtime): self.assertEqual(build.local_state, 'testing') build._schedule() # too fast, docker not started self.assertEqual(build.local_state, 'testing') + self.assertEqual(build.local_result, 'ok') self.start_patcher('fetch_local_logs', 'odoo.addons.runbot.models.host.Host._fetch_local_logs', []) # the local logs have to be empty build.write({'job_start': datetime.datetime.now() - datetime.timedelta(seconds=70)}) # docker never started build._schedule() self.assertEqual(build.local_state, 'done') - self.assertEqual(build.local_result, 'ok') + self.assertEqual(build.local_result, 'ko') diff --git a/runbot/tests/test_upgrade.py b/runbot/tests/test_upgrade.py index e8c9ce215..0cc52b687 100644 --- a/runbot/tests/test_upgrade.py +++ b/runbot/tests/test_upgrade.py @@ -1,6 +1,7 @@ import getpass import logging import getpass +from unittest.mock import patch, mock_open from odoo.exceptions import UserError from odoo.tools import mute_logger from .common import RunbotCase @@ -272,7 +273,7 @@ def test_all(self): upgrade_current_build = batch.slot_ids.filtered(lambda slot: slot.trigger_id == self.trigger_upgrade_server).build_id host = self.env['runbot.host']._get_current() upgrade_current_build.host = host.name - upgrade_current_build._init_pendings(host) + upgrade_current_build._schedule() self.start_patcher('fetch_local_logs', 'odoo.addons.runbot.models.host.Host._fetch_local_logs', []) # the local logs have to be empty upgrade_current_build._schedule() self.assertEqual(upgrade_current_build.local_state, 'done') @@ -298,7 +299,7 @@ def assertOk(build, t, f, b_type, db_suffix, trigger): upgrade_build = batch.slot_ids.filtered(lambda slot: slot.trigger_id == self.trigger_upgrade).build_id host = self.env['runbot.host']._get_current() upgrade_build.host = host.name - upgrade_build._init_pendings(host) + upgrade_build._schedule() upgrade_build._schedule() self.assertEqual(upgrade_build.local_state, 'done') self.assertEqual(len(upgrade_build.children_ids), 2) @@ -339,7 +340,7 @@ def assertOk(build, t, f, b_type, db_suffix, trigger): upgrade_nightly = batch.slot_ids.filtered(lambda slot: slot.trigger_id == trigger_upgrade_addons_nightly).build_id host = self.env['runbot.host']._get_current() upgrade_nightly.host = host.name - upgrade_nightly._init_pendings(host) + upgrade_nightly._schedule() upgrade_nightly._schedule() to_version_builds = upgrade_nightly.children_ids self.assertEqual(upgrade_nightly.local_state, 'done') @@ -353,9 +354,14 @@ def assertOk(build, t, f, b_type, db_suffix, trigger): [] ) to_version_builds.host = host.name - to_version_builds._init_pendings(host) - to_version_builds._schedule() - self.assertEqual(to_version_builds.mapped('local_state'), ['done']*4) + for build in to_version_builds: + build._schedule() # starts builds + self.assertEqual(build.local_state, 'testing') + build._schedule() # makes result and end build + self.assertEqual(build.local_state, 'done') + + self.assertEqual(to_version_builds.mapped('global_state'), ['done', 'waiting', 'waiting', 'waiting'], 'One build have no child, other should wait for children') + from_version_builds = to_version_builds.children_ids self.assertEqual( [ @@ -368,9 +374,15 @@ def assertOk(build, t, f, b_type, db_suffix, trigger): ['11.0->12.0', 'saas-11.3->12.0', '12.0->13.0', 'saas-12.3->13.0', '13.0->master', 'saas-13.1->master', 'saas-13.2->master', 'saas-13.3->master'] ) from_version_builds.host = host.name - from_version_builds._init_pendings(host) - from_version_builds._schedule() - self.assertEqual(from_version_builds.mapped('local_state'), ['done']*8) + for build in from_version_builds: + build._schedule() + self.assertEqual(build.local_state, 'testing') + build._schedule() + self.assertEqual(build.local_state, 'done') + + + self.assertEqual(from_version_builds.mapped('global_state'), ['waiting'] * 8) + db_builds = from_version_builds.children_ids self.assertEqual(len(db_builds), 40) @@ -405,61 +417,73 @@ def assertOk(build, t, f, b_type, db_suffix, trigger): [b.params_id.dump_db.db_suffix for b in b133_master], ['account', 'l10n_be', 'l10n_ch', 'mail', 'stock'] # is this order ok? ) + current_build = db_builds[0] + for current_build in db_builds: + self.start_patcher('docker_state', 'odoo.addons.runbot.models.build.docker_state', 'END') + + suffix = current_build.params_id.dump_db.db_suffix + source_dest = current_build.params_id.dump_db.build_id.dest + def docker_run_restore(cmd, *args, **kwargs): + dump_url = f'http://host.runbot.com/runbot/static/build/{source_dest}/logs/{source_dest}-{suffix}.zip' + zip_name = f'{source_dest}-{suffix}.zip' + db_name = f'{current_build.dest}-{suffix}' + self.assertEqual( + str(cmd).split(' && '), + [ + 'mkdir /data/build/restore', + 'cd /data/build/restore', + f'wget {dump_url}', + f'unzip -q {zip_name}', + 'echo "### restoring filestore"', + f'mkdir -p /data/build/datadir/filestore/{db_name}', + f'mv filestore/* /data/build/datadir/filestore/{db_name}', + 'echo "### restoring db"', + f'psql -q {db_name} < dump.sql', + 'cd /data/build', + 'echo "### cleaning"', + 'rm -r restore', + 'echo "### listing modules"', + f'psql {db_name} -c "select name from ir_module_module where state = \'installed\'" -t -A > /data/build/logs/restore_modules_installed.txt', + 'echo "### restore" "successful"' + ] + ) + self.patchers['docker_run'].side_effect = docker_run_restore + current_build.host = host.name + current_build._schedule()() + self.patchers['docker_run'].assert_called() + + def docker_run_upgrade(cmd, *args, ro_volumes=False, **kwargs): + user = getpass.getuser() + self.assertTrue(ro_volumes.pop(f'/home/{user}/.odoorc').startswith('/tmp/runbot_test/static/build/')) + self.assertEqual( + list(ro_volumes.keys()), [ + '/data/build/addons', + '/data/build/server', + '/data/build/upgrade', + ], + "other commit should have been added automaticaly" + ) + self.assertEqual( + str(cmd), + 'python3 server/server.py {addons_path} --no-xmlrpcs --no-netrpc -u all -d {db_name} --stop-after-init --max-cron-threads=0'.format( + addons_path='--addons-path addons,server/addons,server/core/addons', + db_name=f'{current_build.dest}-{suffix}') + ) + self.patchers['docker_run'].side_effect = docker_run_upgrade + current_build._schedule()() - first_build = db_builds[0] - - self.start_patcher('docker_state', 'odoo.addons.runbot.models.build.docker_state', 'END') - - def docker_run_restore(cmd, *args, **kwargs): - source_dest = first_build.params_id.dump_db.build_id.dest - dump_url='http://host.runbot.com/runbot/static/build/%s/logs/%s-account.zip' % (source_dest, source_dest) - zip_name='%s-account.zip' % source_dest - db_name='%s-master-account' % str(first_build.id).zfill(5) - self.assertEqual( - str(cmd).split(' && '), - [ - 'mkdir /data/build/restore', - 'cd /data/build/restore', - f'wget {dump_url}', - f'unzip -q {zip_name}', - 'echo "### restoring filestore"', - f'mkdir -p /data/build/datadir/filestore/{db_name}', - f'mv filestore/* /data/build/datadir/filestore/{db_name}', - 'echo "### restoring db"', - f'psql -q {db_name} < dump.sql', - 'cd /data/build', - 'echo "### cleaning"', - 'rm -r restore', - 'echo "### listing modules"', - f'psql {db_name} -c "select name from ir_module_module where state = \'installed\'" -t -A > /data/build/logs/restore_modules_installed.txt', - 'echo "### restore" "successful"' - ] - ) - self.patchers['docker_run'].side_effect = docker_run_restore - first_build.host = host.name - first_build._init_pendings(host) - self.patchers['docker_run'].assert_called() - - def docker_run_upgrade(cmd, *args, ro_volumes=False, **kwargs): - user = getpass.getuser() - self.assertTrue(ro_volumes.pop(f'/home/{user}/.odoorc').startswith('/tmp/runbot_test/static/build/')) - self.assertEqual( - ro_volumes, { - '/data/build/addons': '/tmp/runbot_test/static/sources/addons/addons120', - '/data/build/server': '/tmp/runbot_test/static/sources/server/server120', - '/data/build/upgrade': '/tmp/runbot_test/static/sources/upgrade/123abc789', - }, - "other commit should have been added automaticaly" - ) - self.assertEqual( - str(cmd), - 'python3 server/server.py {addons_path} --no-xmlrpcs --no-netrpc -u all -d {db_name} --stop-after-init --max-cron-threads=0'.format( - addons_path='--addons-path addons,server/addons,server/core/addons', - db_name='%s-master-account' % str(first_build.id).zfill(5)) - ) - self.patchers['docker_run'].side_effect = docker_run_upgrade - first_build._schedule() - self.assertEqual(self.patchers['docker_run'].call_count, 2) + with patch('builtins.open', mock_open(read_data='')): + current_build._schedule() + self.assertEqual(current_build.local_state, 'done') + + self.assertEqual(current_build.global_state, 'done') + #self.assertEqual(current_build.global_result, 'ok') + + self.assertEqual(self.patchers['docker_run'].call_count, 80) + + self.assertEqual(from_version_builds.mapped('global_state'), ['done'] * 8) + + self.assertEqual(to_version_builds.mapped('global_state'), ['done'] * 4) # test_build_references batch = self.master_bundle._force() @@ -525,7 +549,7 @@ def docker_run_upgrade(cmd, *args, ro_volumes=False, **kwargs): for db in ['base', 'all', 'no-demo-all']: upgrade_complement_build_13.database_ids = [(0, 0, {'name': '%s-%s' % (upgrade_complement_build_13.dest, db)})] - upgrade_complement_build_13._init_pendings(host) + upgrade_complement_build_13._schedule() self.assertEqual(len(upgrade_complement_build_13.children_ids), 5) master_child = upgrade_complement_build_13.children_ids[0] diff --git a/runbot/views/build_views.xml b/runbot/views/build_views.xml index 524999bb9..9b68869b9 100644 --- a/runbot/views/build_views.xml +++ b/runbot/views/build_views.xml @@ -68,7 +68,6 @@ - diff --git a/runbot/views/config_views.xml b/runbot/views/config_views.xml index d10b644be..20accff74 100644 --- a/runbot/views/config_views.xml +++ b/runbot/views/config_views.xml @@ -61,7 +61,6 @@ - diff --git a/runbot_builder/builder.py b/runbot_builder/builder.py index 6745f6ad2..062a84741 100755 --- a/runbot_builder/builder.py +++ b/runbot_builder/builder.py @@ -20,7 +20,7 @@ def on_start(self): repo._update(force=True) def loop_turn(self): - if self.count == 1: # cleanup at second iteration + if self.count == 1: # cleanup at second iteration self.env['runbot.runbot']._source_cleanup() self.env['runbot.build']._local_cleanup() self.env['runbot.runbot']._docker_cleanup()