Really try to emulate the logs format with the test logs. Switch to a simplified flat logs format.

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):
+  def get_log_entries(self, build_id, start_index):
-    """
-    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):
     """ 
     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,
+    log_entries = self._redis.lrange(self._logs_key(build_id), start_index, -1)
-                                     end_index)
     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

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)
+    start = int(request.args.get('start', 0))
-    end = int(request.args.get('end', -1))
 
-    last_command = None
+    count, logs = build_logs.get_log_entries(build.uuid, start)
-    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
 
     response_obj.update({
       'start': start,
-      'end': end,
       'total': count,
       'logs': [log for log in logs],
     })

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.remaining_script = self._generate_script()
-    self.logs = [self._generate_command()]
+    logger.debug('Total script size: %s', len(self.remaining_script))
-    self.commands = [{
+    print('Total script size: %s' % len(self.remaining_script))
-      'index': 0,
+    self._logs = []
-      'message': self.logs[0]['message'],
+
-    }]
-    self.request_counter = 0
-    self._generate_logs()
     self._status = {}
+    self._last_status = {}
 
-  def _get_random_command(self):
+  def advance_script(self, is_get_status):
-    COMMANDS = ['FROM', 'MAINTAINER', 'RUN', 'CMD', 'EXPOSE', 'ENV', 'ADD', 
+    (_, log, status_wrapper) = self.remaining_script.pop(0)
-                'ENTRYPOINT', 'VOLUME', 'USER', 'WORKDIR']
+    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):
+      from data import model
-    self.last_command += 1
+      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 {
+    msg = {
-      'message': 'Step %s: %s %s' % (self.last_command, command, sentence),
+      'message': 'Step %s: %s %s' % (command_num, command, sentence),
-      'is_command': True,
+      'type': self.COMMAND,
     }
-
+    status = deepcopy(self.STATUS_TEMPLATE)
-  def _generate_logs(self):
+    status['total_commands'] = total_commands
-    rand = SystemRandom()
+    status['current_command'] = command_num
-    num_logs = rand.randint(1, 500)
+    return (command_weight, msg, ('building', status))
-    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(),
-        })
 
   @staticmethod
-  def _generate_image_completion(rand_func):
+  def _generate_logs(count):
-    images = {}
+    return [(1, {'message': get_sentence()}, None) for _ in range(count)]
-    for image_id in range(rand_func.randint(1, 11)):
+
-      total = int(math.pow(abs(rand_func.gauss(0, 1000)), 2))
+  @staticmethod
-      current = rand_func.randint(0, total)
+  def _compute_total_completion(statuses, total_images):
-      image_id = 'image_id_%s' % image_id
+    percentage_with_sizes = float(len(statuses.values()))/total_images
-      images[image_id] = {
+    sent_bytes = sum([status[u'current'] for status in statuses.values()])
-        'total': total,
+    total_bytes = sum([status[u'total'] for status in statuses.values()])
-        'current': current,
+    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):
+      for i in range(one_mb, image_size, one_mb):
-    random = SystemRandom()
+        image_completion[image_id]['current'] = i
-    phases = {
+        new_status = deepcopy(push_status_template)
-      'waiting': {},
+        new_status['image_completion'] = deepcopy(image_completion)
-      '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),
-      },
-    }
 
-    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
+    return push_statuses
-    build_obj = model.get_repository_build(self.namespace, self.repository,
-                                           self.test_build_id)
-    build_obj.phase = phase
-    build_obj.save()
 
-    return phases[phase]
+  @maybe_advance_script()
-
+  def get_log_entries(self, build_id, start_index):
-  def get_log_entries(self, build_id, start_index, end_index):
     if build_id == self.test_build_id:
-      self.request_counter += 1
+      return (len(self._logs), self._logs[start_index:])
-      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])
     else:
-      return super(TestBuildLogs, self).get_log_entries(build_id, start_index,
+      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)
 
+  @maybe_advance_script(True)
   def get_status(self, build_id):
     if build_id == self.test_build_id:
-      self.request_counter += 1
+      returnable_status = self._last_status
-      if self.request_counter % 10 == 0:
+      self._last_status = self._status
-        self._generate_logs()
+      return returnable_status
-      last_status = self._status
-      self._status = self._generate_fake_status()
-      return last_status
     else:
       return super(TestBuildLogs, self).get_status(build_id)

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' %
+    log_appender = partial(build_logs.append_log_message,
-                 (resource_url, tag_name, access_token))
+                           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