diff --git a/data/buildlogs.py b/data/buildlogs.py index d0317c121..bb96ac7dc 100644 --- a/data/buildlogs.py +++ b/data/buildlogs.py @@ -3,6 +3,10 @@ import json class BuildLogs(object): + ERROR = 'error' + COMMAND = 'command' + PHASE = 'phase' + def __init__(self, redis_host): self._redis = redis.StrictRedis(host=redis_host) @@ -10,10 +14,6 @@ class BuildLogs(object): def _logs_key(build_id): return 'builds/%s/logs' % build_id - @staticmethod - def _commands_key(build_id): - return 'builds/%s/commands' % build_id - def append_log_entry(self, build_id, log_obj): """ Appends the serialized form of log_obj to the end of the log entry list @@ -21,7 +21,7 @@ class BuildLogs(object): """ return self._redis.rpush(self._logs_key(build_id), json.dumps(log_obj)) - def append_log_message(self, build_id, log_message): + def append_log_message(self, build_id, log_message, log_type=None): """ Wraps the message in an envelope and push it to the end of the log entry list and returns the index at which it was inserted. @@ -29,54 +29,21 @@ class BuildLogs(object): log_obj = { 'message': log_message } + + if log_type: + log_obj['type'] = log_type + return self._redis.rpush(self._logs_key(build_id), json.dumps(log_obj)) - 1 - def append_command_message(self, build_id, command_message): - """ - Wraps the message in an envelope and push it to the end of the log entry - list, to the commands list, and returns the new length of the list. - """ - log_obj = { - 'message': command_message, - 'is_command': True, - } - idx = self._redis.rpush(self._logs_key(build_id), json.dumps(log_obj)) - 1 - - cmd_obj = { - 'message': command_message, - 'index': idx, - } - self._redis.rpush(self._commands_key(build_id), json.dumps(cmd_obj)) - return idx - - def get_log_entries(self, build_id, start_index, end_index): + def get_log_entries(self, build_id, start_index): """ Returns a tuple of the current length of the list and an iterable of the - requested log entries. End index is inclusive. + requested log entries. """ llen = self._redis.llen(self._logs_key(build_id)) - log_entries = self._redis.lrange(self._logs_key(build_id), start_index, - end_index) + log_entries = self._redis.lrange(self._logs_key(build_id), start_index, -1) return (llen, (json.loads(entry) for entry in log_entries)) - def get_commands(self, build_id): - """ - Returns a list of all Dockerfile commands that have passed through the - specified build thus far. - """ - commands = self._redis.lrange(self._commands_key(build_id), 0, -1) - return (json.loads(cmd) for cmd in commands) - - def get_last_command(self, build_id): - """ - Returns only the last command from the list of commands. - """ - commands = self._redis.lrange(self._commands_key(build_id), -1, -1) - if commands: - return json.loads(commands[-1]) - else: - return None - @staticmethod def _status_key(build_id): return 'builds/%s/status' % build_id diff --git a/endpoints/api.py b/endpoints/api.py index 9990327d5..3d8c216b2 100644 --- a/endpoints/api.py +++ b/endpoints/api.py @@ -1190,38 +1190,12 @@ def get_repo_build_logs(namespace, repository, build_uuid): build = model.get_repository_build(namespace, repository, build_uuid) - start_param = request.args.get('start', None) - end = int(request.args.get('end', -1)) + start = int(request.args.get('start', 0)) - last_command = None - include_commands = request.args.get('commands', 'false') - if include_commands.lower() not in {'0', 'false'}: - commands = [cmd for cmd in build_logs.get_commands(build.uuid)] - response_obj['commands'] = commands - if commands: - last_command = commands[-1] - elif start_param is None: - last_command = build_logs.get_last_command(build.uuid) - - if start_param is None: - if last_command: - start = last_command['index'] - else: - start = 0 - else: - start = int(start_param) - - count, logs = build_logs.get_log_entries(build.uuid, start, end) - - if start < 0: - start = max(0, count + start) - - if end < 0: - end = count + end + count, logs = build_logs.get_log_entries(build.uuid, start) response_obj.update({ 'start': start, - 'end': end, 'total': count, 'logs': [log for log in logs], }) diff --git a/test/testlogs.py b/test/testlogs.py index 8d3b4a156..dffecd3e0 100644 --- a/test/testlogs.py +++ b/test/testlogs.py @@ -1,151 +1,191 @@ -import math import logging from random import SystemRandom from loremipsum import get_sentence +from functools import wraps +from copy import deepcopy from data.buildlogs import BuildLogs -from random import choice logger = logging.getLogger(__name__) +random = SystemRandom() + + +def maybe_advance_script(is_get_status=False): + def inner_advance(func): + @wraps(func) + def wrapper(self, *args, **kwargs): + advance_units = random.randint(1, 500) + logger.debug('Advancing script %s units', advance_units) + while advance_units > 0 and self.remaining_script: + units = self.remaining_script[0][0] + + if advance_units > units: + advance_units -= units + self.advance_script(is_get_status) + else: + break + + return func(self, *args, **kwargs) + return wrapper + return inner_advance class TestBuildLogs(BuildLogs): + COMMAND_TYPES = ['FROM', 'MAINTAINER', 'RUN', 'CMD', 'EXPOSE', 'ENV', 'ADD', + 'ENTRYPOINT', 'VOLUME', 'USER', 'WORKDIR'] + STATUS_TEMPLATE = { + 'total_commands': None, + 'current_command': None, + 'push_completion': 0.0, + 'image_completion': {}, + } + def __init__(self, redis_host, namespace, repository, test_build_id): super(TestBuildLogs, self).__init__(redis_host) self.namespace = namespace self.repository = repository self.test_build_id = test_build_id - self.last_command = 0 - self.logs = [self._generate_command()] - self.commands = [{ - 'index': 0, - 'message': self.logs[0]['message'], - }] - self.request_counter = 0 - self._generate_logs() + self.remaining_script = self._generate_script() + logger.debug('Total script size: %s', len(self.remaining_script)) + print('Total script size: %s' % len(self.remaining_script)) + self._logs = [] + self._status = {} + self._last_status = {} - def _get_random_command(self): - COMMANDS = ['FROM', 'MAINTAINER', 'RUN', 'CMD', 'EXPOSE', 'ENV', 'ADD', - 'ENTRYPOINT', 'VOLUME', 'USER', 'WORKDIR'] + def advance_script(self, is_get_status): + (_, log, status_wrapper) = self.remaining_script.pop(0) + if log is not None: + logger.debug('Writing log line: %s', str(log)) + self._logs.append(log) - return choice(COMMANDS) + if status_wrapper is not None: + (phase, status) = status_wrapper + logger.debug('New status: %s', str(status)) - def _generate_command(self): - self.last_command += 1 + from data import model + build_obj = model.get_repository_build(self.namespace, self.repository, + self.test_build_id) + build_obj.phase = phase + build_obj.save() + self._status = status + if not is_get_status: + self._last_status = status + + def _generate_script(self): + script = [] + + # generate the init phase + script.append(self._generate_phase(400, 'initializing')) + script.extend(self._generate_logs(random.randint(1, 3))) + + # move to the building phase + script.append(self._generate_phase(400, 'building')) + total_commands = random.randint(5, 20) + for command_num in range(1, total_commands + 1): + command_weight = random.randint(50, 100) + script.append(self._generate_command(command_num, total_commands, + command_weight)) + + # we want 0 logs some percent of the time + num_logs = max(0, random.randint(-50, 400)) + script.extend(self._generate_logs(num_logs)) + + # move to the pushing phase + script.append(self._generate_phase(400, 'pushing')) + script.extend(self._generate_push_statuses(total_commands)) + + # move to the error or complete phase + if random.randint(0, 1) == 0: + script.append(self._generate_phase(400, 'complete')) + else: + script.append(self._generate_phase(400, 'error')) + script.append((1, {'message': 'Something bad happened! Oh noes!', + 'type': self.ERROR}, None)) + + return script + + def _generate_phase(self, start_weight, phase_name): + return (start_weight, {'message': phase_name, 'type': self.PHASE}, + (phase_name, deepcopy(self.STATUS_TEMPLATE))) + + def _generate_command(self, command_num, total_commands, command_weight): sentence = get_sentence() - command = self._get_random_command() + command = random.choice(self.COMMAND_TYPES) if command == 'FROM': - sentence = choice(['ubuntu', 'quay.io/devtable/simple', 'quay.io/buynlarge/orgrepo', 'stackbrew/ubuntu:precise']) + sentence = random.choice(['ubuntu', 'quay.io/devtable/simple', + 'quay.io/buynlarge/orgrepo', + 'stackbrew/ubuntu:precise']) - return { - 'message': 'Step %s: %s %s' % (self.last_command, command, sentence), - 'is_command': True, + msg = { + 'message': 'Step %s: %s %s' % (command_num, command, sentence), + 'type': self.COMMAND, } - - def _generate_logs(self): - rand = SystemRandom() - num_logs = rand.randint(1, 500) - for _ in range(num_logs): - if rand.randint(1, 50) == 1: - cmd = self._generate_command() - self.commands.append({ - 'message': cmd['message'], - 'index': len(self.logs), - }) - self.logs.append(cmd) - else: - self.logs.append({ - 'message': get_sentence(), - }) + status = deepcopy(self.STATUS_TEMPLATE) + status['total_commands'] = total_commands + status['current_command'] = command_num + return (command_weight, msg, ('building', status)) @staticmethod - def _generate_image_completion(rand_func): - images = {} - for image_id in range(rand_func.randint(1, 11)): - total = int(math.pow(abs(rand_func.gauss(0, 1000)), 2)) - current = rand_func.randint(0, total) - image_id = 'image_id_%s' % image_id - images[image_id] = { - 'total': total, - 'current': current, + def _generate_logs(count): + return [(1, {'message': get_sentence()}, None) for _ in range(count)] + + @staticmethod + def _compute_total_completion(statuses, total_images): + percentage_with_sizes = float(len(statuses.values()))/total_images + sent_bytes = sum([status[u'current'] for status in statuses.values()]) + total_bytes = sum([status[u'total'] for status in statuses.values()]) + return float(sent_bytes)/total_bytes*percentage_with_sizes + + @staticmethod + def _generate_push_statuses(total_commands): + push_status_template = deepcopy(TestBuildLogs.STATUS_TEMPLATE) + push_status_template['current_command'] = total_commands + push_status_template['total_commands'] = total_commands + + push_statuses = [] + + one_mb = 1 * 1024 * 1024 + + num_images = random.randint(2, 7) + sizes = [random.randint(one_mb, one_mb * 5) for _ in range(num_images)] + + image_completion = {} + for image_num, image_size in enumerate(sizes): + image_id = 'image_id_%s' % image_num + + image_completion[image_id] = { + 'current': 0, + 'total': image_size, } - return images - def _generate_fake_status(self): - random = SystemRandom() - phases = { - 'waiting': {}, - 'starting': { - 'total_commands': 7, - 'current_command': 0, - }, - 'initializing': {}, - 'error': {}, - 'complete': {}, - 'building': { - 'total_commands': 7, - 'current_command': random.randint(1, 7), - }, - 'pushing': { - 'total_commands': 7, - 'current_command': 7, - 'push_completion': random.random(), - 'image_completion': self._generate_image_completion(random), - }, - } + for i in range(one_mb, image_size, one_mb): + image_completion[image_id]['current'] = i + new_status = deepcopy(push_status_template) + new_status['image_completion'] = deepcopy(image_completion) - phase = random.choice(phases.keys()) + completion = TestBuildLogs._compute_total_completion(image_completion, + num_images) + new_status['push_completion'] = completion + push_statuses.append((250, None, ('pushing', new_status))) - from data import model - build_obj = model.get_repository_build(self.namespace, self.repository, - self.test_build_id) - build_obj.phase = phase - build_obj.save() + return push_statuses - return phases[phase] - - def get_log_entries(self, build_id, start_index, end_index): + @maybe_advance_script() + def get_log_entries(self, build_id, start_index): if build_id == self.test_build_id: - self.request_counter += 1 - if self.request_counter % 10 == 0: - self._generate_logs() - logger.debug('Returning logs %s:%s', start_index, end_index) - if end_index >= 0: - end_index += 1 - return (len(self.logs), self.logs[start_index:end_index]) + return (len(self._logs), self._logs[start_index:]) else: - return super(TestBuildLogs, self).get_log_entries(build_id, start_index, - end_index) - - def get_commands(self, build_id): - if build_id == self.test_build_id: - self.request_counter += 1 - if self.request_counter % 10 == 0: - self._generate_logs() - return self.commands - else: - return super(TestBuildLogs, self).get_commands(build_id) - - def get_last_command(self, build_id): - if build_id == self.test_build_id: - self.request_counter += 1 - if self.request_counter % 10 == 0: - self._generate_logs() - return self.commands[-1] - else: - return super(TestBuildLogs, self).get_last_command(build_id) + return super(TestBuildLogs, self).get_log_entries(build_id, start_index) + @maybe_advance_script(True) def get_status(self, build_id): if build_id == self.test_build_id: - self.request_counter += 1 - if self.request_counter % 10 == 0: - self._generate_logs() - last_status = self._status - self._status = self._generate_fake_status() - return last_status + returnable_status = self._last_status + self._last_status = self._status + return returnable_status else: return super(TestBuildLogs, self).get_status(build_id) diff --git a/workers/dockerfilebuild.py b/workers/dockerfilebuild.py index ba4de4093..27531c30c 100644 --- a/workers/dockerfilebuild.py +++ b/workers/dockerfilebuild.py @@ -10,6 +10,7 @@ import shutil from docker import Client, APIError from tempfile import TemporaryFile, mkdtemp from zipfile import ZipFile +from functools import partial from data.queue import dockerfile_build_queue from data import model @@ -53,9 +54,9 @@ class DockerfileBuildContext(object): self._build_dir = build_context_dir self._tag_name = tag_name self._push_token = push_token - self._build_uuid = build_uuid self._cl = Client(timeout=1200, version='1.7') - self._status = StatusWrapper(self._build_uuid) + self._status = StatusWrapper(build_uuid) + self._build_logger = partial(build_logs, build_uuid) dockerfile_path = os.path.join(self._build_dir, "Dockerfile") self._num_steps = DockerfileBuildContext.__count_steps(dockerfile_path) @@ -93,7 +94,7 @@ class DockerfileBuildContext(object): with self._status as status: status['total_commands'] = self._num_steps - logger.debug('Building to tag names: %s' % self._tag_name) + logger.debug('Building to tag named: %s' % self._tag_name) build_status = self._cl.build(path=self._build_dir, tag=self._tag_name, stream=True) @@ -103,14 +104,14 @@ class DockerfileBuildContext(object): logger.debug('Status: %s', str(status.encode('utf-8'))) step_increment = re.search(r'Step ([0-9]+) :', status) if step_increment: - build_logs.append_command_message(str(status)) + self._build_logger(str(status), build_logs.COMMAND) current_step = int(step_increment.group(1)) logger.debug('Step now: %s/%s' % (current_step, self._num_steps)) with self._status as status: status['current_command'] = current_step continue else: - build_logs.append_log_message(self._build_uuid, str(status)) + self._build_logger(str(status)) complete = re.match(r'Successfully built ([a-z0-9]+)$', status) if complete: @@ -260,10 +261,15 @@ class DockerfileBuildWorker(Worker): tag_name = repository_build.tag access_token = repository_build.access_token.code - start_msg = ('Starting job with resource url: %s tag: %s and token: %s' % - (resource_url, tag_name, access_token)) + log_appender = partial(build_logs.append_log_message, + repository_build.uuid) + + log_appender('initializing', build_logs.PHASE) + + start_msg = ('Starting job with resource url: %s tag: %s' % (resource_url, + tag_name)) logger.debug(start_msg) - build_logs.append_log_message(repository_build.uuid, start_msg) + log_appender(start_msg) docker_resource = requests.get(resource_url) c_type = docker_resource.headers['content-type'] @@ -271,13 +277,13 @@ class DockerfileBuildWorker(Worker): filetype_msg = ('Request to build file of type: %s with tag: %s' % (c_type, tag_name)) logger.info(filetype_msg) - build_logs.append_log_message(repository_build.uuid, filetype_msg) + log_appender(filetype_msg) if c_type not in self._mime_processors: raise RuntimeError('Invalid dockerfile content type: %s' % c_type) build_dir = self._mime_processors[c_type](docker_resource) - uuid = repository_build.uuid + log_appender('building', build_logs.PHASE) repository_build.phase = 'building' repository_build.save() @@ -287,24 +293,28 @@ class DockerfileBuildWorker(Worker): built_image = build_ctxt.build() if not built_image: + log_appender('error', build_logs.PHASE) repository_build.phase = 'error' repository_build.save() - build_logs.append_log_message(uuid, 'Unable to build dockerfile.') + log_appender('Unable to build dockerfile.', build_logs.ERROR) return False + log_appender('pushing', build_logs.PHASE) repository_build.phase = 'pushing' repository_build.save() build_ctxt.push(built_image) + log_appender('complete', build_logs.PHASE) repository_build.phase = 'complete' repository_build.save() except Exception as exc: + log_appender('error', build_logs.PHASE) logger.exception('Exception when processing request.') repository_build.phase = 'error' repository_build.save() - build_logs.append_log_message(uuid, exc.message) + log_appender(exc.message, build_logs.ERROR) return False return True