From 6601e83285c840dec783347be7c997a1d0f3b2f1 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Thu, 11 Dec 2014 18:03:40 +0200
Subject: [PATCH 01/19] When speaking to version 0.2-beta of the build worker,
 properly lookup the cached commands and see if we have a matching image/tag
 in the repository

---
 buildman/component/buildcomponent.py | 81 ++++++++++++++++------------
 buildman/jobutil/buildjob.py         | 54 +++++++++++++++++--
 buildman/jobutil/workererror.py      |  5 ++
 data/model/legacy.py                 | 20 ++++++-
 4 files changed, 123 insertions(+), 37 deletions(-)

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index d518d3453..ca56e6926 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -20,7 +20,7 @@ HEARTBEAT_DELTA = datetime.timedelta(seconds=30)
 HEARTBEAT_TIMEOUT = 10
 INITIAL_TIMEOUT = 25
 
-SUPPORTED_WORKER_VERSIONS = ['0.1-beta']
+SUPPORTED_WORKER_VERSIONS = ['0.1-beta', '0.2-beta']
 
 logger = logging.getLogger(__name__)
 
@@ -46,6 +46,7 @@ class BuildComponent(BaseComponent):
     self._current_job = None
     self._build_status = None
     self._image_info = None
+    self._worker_version = None
 
     BaseComponent.__init__(self, config, **kwargs)
 
@@ -55,6 +56,7 @@ class BuildComponent(BaseComponent):
   def onJoin(self, details):
     logger.debug('Registering methods and listeners for component %s', self.builder_realm)
     yield From(self.register(self._on_ready, u'io.quay.buildworker.ready'))
+    yield From(self.register(self._check_cache, u'io.quay.buildworker.checkcache'))
     yield From(self.register(self._ping, u'io.quay.buildworker.ping'))
     yield From(self.subscribe(self._on_heartbeat, 'io.quay.builder.heartbeat'))
     yield From(self.subscribe(self._on_log_message, 'io.quay.builder.logmessage'))
@@ -73,42 +75,45 @@ class BuildComponent(BaseComponent):
 
     self._set_status(ComponentStatus.BUILDING)
 
-    # Retrieve the job's buildpack.
+    base_image_information = {}
+    build_config = build_job.build_config()
+
+    # Retrieve the job's buildpack url.
     buildpack_url = self.user_files.get_file_url(build_job.repo_build().resource_key,
                                                  requires_cors=False)
 
-    logger.debug('Retreiving build package: %s', buildpack_url)
-    buildpack = None
-    try:
-      buildpack = BuildPackage.from_url(buildpack_url)
-    except BuildPackageException as bpe:
-      self._build_failure('Could not retrieve build package', bpe)
-      return
+    # TODO(jschorr): Remove this block andthe buildpack package once we move everyone over
+    # to version 0.2 or higher
+    if self._worker_version == '0.1-beta':
+      logger.debug('Retreiving build package: %s', buildpack_url)
+      buildpack = None
+      try:
+        buildpack = BuildPackage.from_url(buildpack_url)
+      except BuildPackageException as bpe:
+        self._build_failure('Could not retrieve build package', bpe)
+        return
 
-    # Extract the base image information from the Dockerfile.
-    parsed_dockerfile = None
-    logger.debug('Parsing dockerfile')
+      # Extract the base image information from the Dockerfile.
+      parsed_dockerfile = None
+      logger.debug('Parsing dockerfile')
 
-    build_config = build_job.build_config()
-    try:
-      parsed_dockerfile = buildpack.parse_dockerfile(build_config.get('build_subdir'))
-    except BuildPackageException as bpe:
-      self._build_failure('Could not find Dockerfile in build package', bpe)
-      return
+      try:
+        parsed_dockerfile = buildpack.parse_dockerfile(build_config.get('build_subdir'))
+      except BuildPackageException as bpe:
+        self._build_failure('Could not find Dockerfile in build package', bpe)
+        return
 
-    image_and_tag_tuple = parsed_dockerfile.get_image_and_tag()
-    if image_and_tag_tuple is None or image_and_tag_tuple[0] is None:
-      self._build_failure('Missing FROM line in Dockerfile')
-      return
+      image_and_tag_tuple = parsed_dockerfile.get_image_and_tag()
+      if image_and_tag_tuple is None or image_and_tag_tuple[0] is None:
+        self._build_failure('Missing FROM line in Dockerfile')
+        return
 
-    base_image_information = {
-        'repository': image_and_tag_tuple[0],
-        'tag': image_and_tag_tuple[1]
-    }
+      base_image_information['repository'] = image_and_tag_tuple[0]
+      base_image_information['tag'] = image_and_tag_tuple[1]
 
-    # Extract the number of steps from the Dockerfile.
-    with self._build_status as status_dict:
-      status_dict['total_commands'] = len(parsed_dockerfile.commands)
+      # Extract the number of steps from the Dockerfile.
+      with self._build_status as status_dict:
+        status_dict['total_commands'] = len(parsed_dockerfile.commands)
 
     # Add the pull robot information, if any.
     if build_config.get('pull_credentials') is not None:
@@ -128,20 +133,20 @@ class BuildComponent(BaseComponent):
     #  push_token: The token to use to push the built image.
     #  tag_names: The name(s) of the tag(s) for the newly built image.
     #  base_image: The image name and credentials to use to conduct the base image pull.
-    #   repository: The repository to pull.
-    #   tag: The tag to pull.
+    #   repository: The repository to pull (DEPRECATED)
+    #   tag: The tag to pull               (DEPRECATED)
     #   username: The username for pulling the base image (if any).
     #   password: The password for pulling the base image (if any).
     build_arguments = {
         'build_package': buildpack_url,
         'sub_directory': build_config.get('build_subdir', ''),
         'repository': repository_name,
-        'registry': self.server_hostname,
+        'registry': '10.0.2.2:5000' or self.server_hostname,
         'pull_token': build_job.repo_build().access_token.code,
         'push_token': build_job.repo_build().access_token.code,
         'tag_names': build_config.get('docker_tags', ['latest']),
         'base_image': base_image_information,
-        'cached_tag': build_job.determine_cached_tag() or ''
+        'cached_tag': build_job.determine_cached_tag() or '' # Remove after V0.1-beta is deprecated
     }
 
     # Invoke the build.
@@ -283,6 +288,15 @@ class BuildComponent(BaseComponent):
     """ Ping pong. """
     return 'pong'
 
+  def _check_cache(self, cache_commands, base_image_name, base_image_tag, base_image_id):
+    with self._build_status as status_dict:
+      status_dict['total_commands'] = len(cache_commands) + 1
+
+    logger.debug('Checking cache on realm %s. Base image: %s:%s (%s)', self.builder_realm,
+                 base_image_name, base_image_tag, base_image_id)
+
+    return self._current_job.determine_cached_tag(base_image_id, cache_commands) or ''
+
   def _on_ready(self, token, version):
     if not version in SUPPORTED_WORKER_VERSIONS:
       logger.warning('Build component (token "%s") is running an out-of-date version: %s', version)
@@ -296,6 +310,7 @@ class BuildComponent(BaseComponent):
       logger.warning('Builder token mismatch. Expected: "%s". Found: "%s"', self.expected_token, token)
       return False
 
+    self._worker_version = version
     self._set_status(ComponentStatus.RUNNING)
 
     # Start the heartbeat check and updating loop.
diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index 6ec02a830..63d544790 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -31,10 +31,58 @@ class BuildJob(object):
           'Could not parse repository build job config with ID %s' % self._job_details['build_uuid']
       )
 
-  def determine_cached_tag(self):
+  def determine_cached_tag(self, base_image_id=None, cache_comments=None):
     """ Returns the tag to pull to prime the cache or None if none. """
-    # TODO(jschorr): Change this to use the more complicated caching rules, once we have caching
-    # be a pull of things besides the constructed tags.
+    cached_tag = None
+    if base_image_id and cache_comments:
+      cached_tag = self._determine_cached_tag_by_comments(base_image_id, cache_comments)
+
+    if not cached_tag:
+      cached_tag = self._determine_cached_tag_by_tag()
+
+    return cached_tag
+
+  def _determine_cached_tag_by_comments(self, base_image_id, cache_commands):
+    """ Determines the tag to use for priming the cache for this build job, by matching commands
+        starting at the given base_image_id. This mimics the Docker cache checking, so it should,
+        in theory, provide "perfect" caching.
+    """
+    # Lookup the base image in the repository. If it doesn't exist, nothing more to do.
+    repo_namespace = self._repo_build.repository.namespace_user.username
+    repo_name = self._repo_build.repository.name
+
+    repository = model.get_repository(repo_namespace, repo_name)
+    if repository is None:
+      # Should never happen, but just to be sure.
+      return None
+
+    current_image = model.get_image(repository, base_image_id)
+    if current_image is None:
+      return None
+
+    # For each cache comment, find a child image that matches the command.
+    for cache_command in cache_commands:
+      print current_image.docker_image_id
+
+      current_image = model.find_child_image(repository, current_image, cache_command)
+      if current_image is None:
+        return None
+
+    # Find a tag associated with the image, if any.
+    # TODO(jschorr): We should just return the image ID instead of a parent tag, OR we should
+    # make this more efficient.
+    for tag in model.list_repository_tags(repo_namespace, repo_name):
+      tag_image = tag.image
+      ancestor_index = '/%s/' % current_image.id
+      if ancestor_index in tag_image.ancestors:
+        return tag.name
+
+    return None
+
+  def _determine_cached_tag_by_tag(self):
+    """ Determines the cached tag by looking for one of the tags being built, and seeing if it
+        exists in the repository. This is a fallback for when no comment information is available.
+    """
     tags = self._build_config.get('docker_tags', ['latest'])
     existing_tags = model.list_repository_tags(self._repo_build.repository.namespace_user.username,
                                                self._repo_build.repository.name)
diff --git a/buildman/jobutil/workererror.py b/buildman/jobutil/workererror.py
index 8271976e4..580d46f4d 100644
--- a/buildman/jobutil/workererror.py
+++ b/buildman/jobutil/workererror.py
@@ -57,6 +57,11 @@ class WorkerError(object):
         'io.quay.builder.missingorinvalidargument': {
             'message': 'Missing required arguments for builder',
             'is_internal': True
+        },
+
+        'io.quay.builder.cachelookupissue': {
+            'message': 'Error checking for a cached tag',
+            'is_internal': True
         }
     }
 
diff --git a/data/model/legacy.py b/data/model/legacy.py
index a5c779871..225b5bf2e 100644
--- a/data/model/legacy.py
+++ b/data/model/legacy.py
@@ -1089,6 +1089,25 @@ def get_repository(namespace_name, repository_name):
     return None
 
 
+def get_image(repo, dockerfile_id):
+  try:
+    return Image.get(Image.docker_image_id == dockerfile_id, Image.repository == repo)
+  except Image.DoesNotExist:
+    return None
+
+
+def find_child_image(repo, parent_image, command):
+  try:
+    return (Image.select()
+                .join(ImageStorage)
+                .switch(Image)
+                .where(Image.ancestors % '%/' + parent_image.id + '/%',
+                       ImageStorage.command == command)
+                .get())
+  except Image.DoesNotExist:
+    return None
+
+
 def get_repo_image(namespace_name, repository_name, docker_image_id):
   def limit_to_image_id(query):
     return query.where(Image.docker_image_id == docker_image_id).limit(1)
@@ -1645,7 +1664,6 @@ def get_tag_image(namespace_name, repository_name, tag_name):
   else:
     return images[0]
 
-
 def get_image_by_id(namespace_name, repository_name, docker_image_id):
   image = get_repo_image_extended(namespace_name, repository_name, docker_image_id)
   if not image:

From 00299ca60ffcdc77b64fb388fcb2d30613ae09ab Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Thu, 11 Dec 2014 18:17:15 +0200
Subject: [PATCH 02/19] We need to make sure to use the *full* command

---
 buildman/jobutil/buildjob.py | 5 ++---
 1 file changed, 2 insertions(+), 3 deletions(-)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index 63d544790..d5514a958 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -62,9 +62,8 @@ class BuildJob(object):
 
     # For each cache comment, find a child image that matches the command.
     for cache_command in cache_commands:
-      print current_image.docker_image_id
-
-      current_image = model.find_child_image(repository, current_image, cache_command)
+      full_command = '["/bin/sh", "-c", "%s"]' % cache_command
+      current_image = model.find_child_image(repository, current_image, full_command)
       if current_image is None:
         return None
 

From 0065ac8503e0cc80125e7d74de02a1aee35853e1 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 12:13:40 -0500
Subject: [PATCH 03/19] Add back in the cache checking code and remove the old
 0.1 build pack code

---
 buildman/component/buildcomponent.py | 57 ++++--------------
 buildman/jobutil/buildpack.py        | 88 ----------------------------
 buildman/jobutil/buildstatus.py      |  2 +-
 3 files changed, 14 insertions(+), 133 deletions(-)
 delete mode 100644 buildman/jobutil/buildpack.py

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index c1fb41a02..be0e17d7f 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -10,7 +10,6 @@ from autobahn.wamp.exception import ApplicationError
 from buildman.server import BuildJobResult
 from buildman.component.basecomponent import BaseComponent
 from buildman.jobutil.buildjob import BuildJobLoadException
-from buildman.jobutil.buildpack import BuildPackage, BuildPackageException
 from buildman.jobutil.buildstatus import StatusHandler
 from buildman.jobutil.workererror import WorkerError
 
@@ -20,7 +19,7 @@ HEARTBEAT_DELTA = datetime.timedelta(seconds=30)
 HEARTBEAT_TIMEOUT = 10
 INITIAL_TIMEOUT = 25
 
-SUPPORTED_WORKER_VERSIONS = ['0.1-beta', '0.2']
+SUPPORTED_WORKER_VERSIONS = ['0.2']
 
 logger = logging.getLogger(__name__)
 
@@ -56,7 +55,10 @@ class BuildComponent(BaseComponent):
   def onJoin(self, details):
     logger.debug('Registering methods and listeners for component %s', self.builder_realm)
     yield trollius.From(self.register(self._on_ready, u'io.quay.buildworker.ready'))
+    yield trollius.From(self.register(self._determine_cache_tag,
+                                      u'io.quay.buildworker.determinecachetag'))
     yield trollius.From(self.register(self._ping, u'io.quay.buildworker.ping'))
+
     yield trollius.From(self.subscribe(self._on_heartbeat, 'io.quay.builder.heartbeat'))
     yield trollius.From(self.subscribe(self._on_log_message, 'io.quay.builder.logmessage'))
 
@@ -91,46 +93,6 @@ class BuildComponent(BaseComponent):
     buildpack_url = self.user_files.get_file_url(build_job.repo_build.resource_key,
                                                  requires_cors=False)
 
-    # TODO(jschorr): Remove as soon as the fleet has been transitioned to 0.2.
-    if self._worker_version == '0.1-beta':
-      # Retrieve the job's buildpack.
-      logger.debug('Retrieving build package: %s', buildpack_url)
-      buildpack = None
-      try:
-        buildpack = BuildPackage.from_url(buildpack_url)
-      except BuildPackageException as bpe:
-        self._build_failure('Could not retrieve build package', bpe)
-        raise trollius.Return()
-
-      # Extract the base image information from the Dockerfile.
-      parsed_dockerfile = None
-      logger.debug('Parsing dockerfile')
-
-      try:
-        parsed_dockerfile = buildpack.parse_dockerfile(build_config.get('build_subdir'))
-      except BuildPackageException as bpe:
-        self._build_failure('Could not find Dockerfile in build package', bpe)
-        raise trollius.Return()
-
-      image_and_tag_tuple = parsed_dockerfile.get_image_and_tag()
-      if image_and_tag_tuple is None or image_and_tag_tuple[0] is None:
-        self._build_failure('Missing FROM line in Dockerfile')
-        raise trollius.Return()
-
-      base_image_information = {
-          'repository': image_and_tag_tuple[0],
-          'tag': image_and_tag_tuple[1]
-      }
-
-      # Extract the number of steps from the Dockerfile.
-      with self._build_status as status_dict:
-        status_dict['total_commands'] = len(parsed_dockerfile.commands)
-    else:
-      # TODO(jschorr): This is a HACK to make sure the progress bar (sort of) continues working
-      # until such time as we have the caching code in place.
-      with self._build_status as status_dict:
-        status_dict['total_commands'] = 25
-
     # Add the pull robot information, if any.
     if build_job.pull_credentials:
       base_image_information['username'] = build_job.pull_credentials.get('username', '')
@@ -161,8 +123,7 @@ class BuildComponent(BaseComponent):
         'pull_token': build_job.repo_build.access_token.code,
         'push_token': build_job.repo_build.access_token.code,
         'tag_names': build_config.get('docker_tags', ['latest']),
-        'base_image': base_image_information,
-        'cached_tag': build_job.determine_cached_tag() or ''
+        'base_image': base_image_information
     }
 
     # Invoke the build.
@@ -256,6 +217,14 @@ class BuildComponent(BaseComponent):
     elif phase == BUILD_PHASE.BUILDING:
       self._build_status.append_log(current_status_string)
 
+  def _determine_cache_tag(self, cache_commands, base_image_name, base_image_tag, base_image_id):
+    with self._build_status as status_dict:
+      status_dict['total_commands'] = len(cache_commands) + 1
+
+    logger.debug('Checking cache on realm %s. Base image: %s:%s (%s)', self.builder_realm,
+                 base_image_name, base_image_tag, base_image_id)
+
+    return self._current_job.determine_cached_tag(base_image_id, cache_commands) or ''
 
   def _build_failure(self, error_message, exception=None):
     """ Handles and logs a failed build. """
diff --git a/buildman/jobutil/buildpack.py b/buildman/jobutil/buildpack.py
deleted file mode 100644
index 9892c65d3..000000000
--- a/buildman/jobutil/buildpack.py
+++ /dev/null
@@ -1,88 +0,0 @@
-import tarfile
-import requests
-import os
-
-from tempfile import TemporaryFile, mkdtemp
-from zipfile import ZipFile
-from util.dockerfileparse import parse_dockerfile
-from util.safetar import safe_extractall
-
-class BuildPackageException(Exception):
-  """ Exception raised when retrieving or parsing a build package. """
-  pass
-
-
-class BuildPackage(object):
-  """ Helper class for easy reading and updating of a Dockerfile build pack. """
-
-  def __init__(self, requests_file):
-    self._mime_processors = {
-        'application/zip': BuildPackage._prepare_zip,
-        'application/x-zip-compressed': BuildPackage._prepare_zip,
-        'text/plain': BuildPackage._prepare_dockerfile,
-        'application/octet-stream': BuildPackage._prepare_dockerfile,
-        'application/x-tar': BuildPackage._prepare_tarball,
-        'application/gzip': BuildPackage._prepare_tarball,
-        'application/x-gzip': BuildPackage._prepare_tarball,
-    }
-
-    c_type = requests_file.headers['content-type']
-    c_type = c_type.split(';')[0] if ';' in c_type else c_type
-
-    if c_type not in self._mime_processors:
-      raise BuildPackageException('Unknown build package mime type: %s' % c_type)
-
-    self._package_directory = None
-    try:
-      self._package_directory = self._mime_processors[c_type](requests_file)
-    except Exception as ex:
-      raise BuildPackageException(ex.message)
-
-  def parse_dockerfile(self, subdirectory):
-    dockerfile_path = os.path.join(self._package_directory, subdirectory, 'Dockerfile')
-    if not os.path.exists(dockerfile_path):
-      if subdirectory:
-        message = 'Build package did not contain a Dockerfile at sub directory %s.' % subdirectory
-      else:
-        message = 'Build package did not contain a Dockerfile at the root directory.'
-
-      raise BuildPackageException(message)
-
-    with open(dockerfile_path, 'r') as dockerfileobj:
-      return parse_dockerfile(dockerfileobj.read())
-
-  @staticmethod
-  def from_url(url):
-    buildpack_resource = requests.get(url, stream=True)
-    return BuildPackage(buildpack_resource)
-
-  @staticmethod
-  def _prepare_zip(request_file):
-    build_dir = mkdtemp(prefix='docker-build-')
-
-    # Save the zip file to temp somewhere
-    with TemporaryFile() as zip_file:
-      zip_file.write(request_file.content)
-      to_extract = ZipFile(zip_file)
-      to_extract.extractall(build_dir)
-
-    return build_dir
-
-  @staticmethod
-  def _prepare_dockerfile(request_file):
-    build_dir = mkdtemp(prefix='docker-build-')
-    dockerfile_path = os.path.join(build_dir, "Dockerfile")
-    with open(dockerfile_path, 'w') as dockerfile:
-      dockerfile.write(request_file.content)
-
-    return build_dir
-
-  @staticmethod
-  def _prepare_tarball(request_file):
-    build_dir = mkdtemp(prefix='docker-build-')
-
-    # Save the zip file to temp somewhere
-    with tarfile.open(mode='r|*', fileobj=request_file.raw) as tar_stream:
-      safe_extractall(tar_stream, build_dir)
-
-    return build_dir
diff --git a/buildman/jobutil/buildstatus.py b/buildman/jobutil/buildstatus.py
index 217e3aa6c..393ecd3b4 100644
--- a/buildman/jobutil/buildstatus.py
+++ b/buildman/jobutil/buildstatus.py
@@ -11,7 +11,7 @@ class StatusHandler(object):
     self._build_logs = build_logs
 
     self._status = {
-        'total_commands': None,
+        'total_commands': 0,
         'current_command': None,
         'push_completion': 0.0,
         'pull_completion': 0.0,

From 4310f47dee9ffc704841b987033c68bfd3641bfe Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 12:16:43 -0500
Subject: [PATCH 04/19] Some code cleanup in the cached tag determination code

---
 buildman/jobutil/buildjob.py | 17 ++++++-----------
 1 file changed, 6 insertions(+), 11 deletions(-)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index c69023aca..e507dab5f 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -82,15 +82,11 @@ class BuildJob(object):
         in theory, provide "perfect" caching.
     """
     # Lookup the base image in the repository. If it doesn't exist, nothing more to do.
-    repo_namespace = self._repo_build.repository.namespace_user.username
-    repo_name = self._repo_build.repository.name
+    repo_build = self.repo_build
+    repo_namespace = repo_build.repository.namespace_user.username
+    repo_name = repo_build.repository.name
 
-    repository = model.get_repository(repo_namespace, repo_name)
-    if repository is None:
-      # Should never happen, but just to be sure.
-      return None
-
-    current_image = model.get_image(repository, base_image_id)
+    current_image = model.get_image(repo_build.repository, base_image_id)
     if current_image is None:
       return None
 
@@ -117,9 +113,8 @@ class BuildJob(object):
         exists in the repository. This is a fallback for when no comment information is available.
     """
     tags = self._build_config.get('docker_tags', ['latest'])
-    existing_tags = model.list_repository_tags(self._repo_build.repository.namespace_user.username,
-                                               self._repo_build.repository.name)
-
+    repository = self.repo_build.repository
+    existing_tags = model.list_repository_tags(repository.namespace_user.username, repository.name)
     cached_tags = set(tags) & set([tag.name for tag in existing_tags])
     if cached_tags:
       return list(cached_tags)[0]

From 6cb1212da638aefdffaa072750affa1c75200226 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 13:54:14 -0500
Subject: [PATCH 05/19] Add logging

---
 buildman/jobutil/buildjob.py | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index e507dab5f..e53b9bcb2 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -1,9 +1,12 @@
 import json
+import logging
 
 from cachetools import lru_cache
 from endpoints.notificationhelper import spawn_notification
 from data import model
 
+logger = logging.getLogger(__name__)
+
 
 class BuildJobLoadException(Exception):
   """ Exception raised if a build job could not be instantiated for some reason. """
@@ -74,6 +77,8 @@ class BuildJob(object):
     if not cached_tag:
       cached_tag = self._determine_cached_tag_by_tag()
 
+    logger.debug('Determined cached tag %s for %s: %s', cached_tag, base_image_id, cache_comments)
+
     return cached_tag
 
   def _determine_cached_tag_by_comments(self, base_image_id, cache_commands):

From 384d0eba6f275206fb28566e8262e969585e5dca Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 14:12:24 -0500
Subject: [PATCH 06/19] Fix cache command argument

---
 buildman/component/buildcomponent.py | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index be0e17d7f..5cac57afe 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -217,14 +217,14 @@ class BuildComponent(BaseComponent):
     elif phase == BUILD_PHASE.BUILDING:
       self._build_status.append_log(current_status_string)
 
-  def _determine_cache_tag(self, cache_commands, base_image_name, base_image_tag, base_image_id):
+  def _determine_cache_tag(self, command_comments, base_image_name, base_image_tag, base_image_id):
     with self._build_status as status_dict:
-      status_dict['total_commands'] = len(cache_commands) + 1
+      status_dict['total_commands'] = len(command_comments) + 1
 
     logger.debug('Checking cache on realm %s. Base image: %s:%s (%s)', self.builder_realm,
                  base_image_name, base_image_tag, base_image_id)
 
-    return self._current_job.determine_cached_tag(base_image_id, cache_commands) or ''
+    return self._current_job.determine_cached_tag(base_image_id, command_comments) or ''
 
   def _build_failure(self, error_message, exception=None):
     """ Handles and logs a failed build. """

From 9b0e43514b52f6fa10dcce47d0dca4c3131af665 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 14:53:18 -0500
Subject: [PATCH 07/19] Fix typos

---
 buildman/component/buildcomponent.py | 4 +++-
 buildman/jobutil/buildjob.py         | 2 +-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index 5cac57afe..f7e2ff253 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -217,6 +217,7 @@ class BuildComponent(BaseComponent):
     elif phase == BUILD_PHASE.BUILDING:
       self._build_status.append_log(current_status_string)
 
+  @trollius.coroutine
   def _determine_cache_tag(self, command_comments, base_image_name, base_image_tag, base_image_id):
     with self._build_status as status_dict:
       status_dict['total_commands'] = len(command_comments) + 1
@@ -224,7 +225,8 @@ class BuildComponent(BaseComponent):
     logger.debug('Checking cache on realm %s. Base image: %s:%s (%s)', self.builder_realm,
                  base_image_name, base_image_tag, base_image_id)
 
-    return self._current_job.determine_cached_tag(base_image_id, command_comments) or ''
+    tag_found = self._current_job.determine_cached_tag(base_image_id, command_comments)
+    raise trollius.Return(tag_found or '')
 
   def _build_failure(self, error_message, exception=None):
     """ Handles and logs a failed build. """
diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index e53b9bcb2..fcf5dcfef 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -117,7 +117,7 @@ class BuildJob(object):
     """ Determines the cached tag by looking for one of the tags being built, and seeing if it
         exists in the repository. This is a fallback for when no comment information is available.
     """
-    tags = self._build_config.get('docker_tags', ['latest'])
+    tags = self.build_config.get('docker_tags', ['latest'])
     repository = self.repo_build.repository
     existing_tags = model.list_repository_tags(repository.namespace_user.username, repository.name)
     cached_tags = set(tags) & set([tag.name for tag in existing_tags])

From b0e315c332359f6d59427833382bbc9d3b28464d Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 15:48:36 -0500
Subject: [PATCH 08/19] Fix issues in cache comment comparison

---
 buildman/jobutil/buildjob.py | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index fcf5dcfef..4d85a76c1 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -98,17 +98,19 @@ class BuildJob(object):
     # For each cache comment, find a child image that matches the command.
     for cache_command in cache_commands:
       full_command = '["/bin/sh", "-c", "%s"]' % cache_command
-      current_image = model.find_child_image(repository, current_image, full_command)
+      current_image = model.find_child_image(repo_build.repository, current_image, full_command)
       if current_image is None:
         return None
 
+      logger.debug('Found cached image %s for comment %s', current_image.id, full_command)
+
     # Find a tag associated with the image, if any.
     # TODO(jschorr): We should just return the image ID instead of a parent tag, OR we should
     # make this more efficient.
     for tag in model.list_repository_tags(repo_namespace, repo_name):
       tag_image = tag.image
       ancestor_index = '/%s/' % current_image.id
-      if ancestor_index in tag_image.ancestors:
+      if ancestor_index in tag_image.ancestors or tag_image.id == current_image.id:
         return tag.name
 
     return None

From 9f1ec9d47dda198110a2db0d0631a6cd535b79ec Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 16:29:15 -0500
Subject: [PATCH 09/19] Fix loading of partial caching under a tag

---
 buildman/jobutil/buildjob.py | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index 4d85a76c1..bcf2c33c2 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -92,16 +92,18 @@ class BuildJob(object):
     repo_name = repo_build.repository.name
 
     current_image = model.get_image(repo_build.repository, base_image_id)
+    next_image = None
     if current_image is None:
       return None
 
     # For each cache comment, find a child image that matches the command.
     for cache_command in cache_commands:
       full_command = '["/bin/sh", "-c", "%s"]' % cache_command
-      current_image = model.find_child_image(repo_build.repository, current_image, full_command)
-      if current_image is None:
-        return None
+      next_image = model.find_child_image(repo_build.repository, current_image, full_command)
+      if next_image is None:
+        break
 
+      current_image = next_image
       logger.debug('Found cached image %s for comment %s', current_image.id, full_command)
 
     # Find a tag associated with the image, if any.

From 3d31c64da201cf75fa5eb7e64a6fd28c42097075 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 16:45:06 -0500
Subject: [PATCH 10/19] Make sure to select the latest image in the repository
 with the matching comment

---
 data/model/legacy.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/data/model/legacy.py b/data/model/legacy.py
index 12220d168..ff1a5ba59 100644
--- a/data/model/legacy.py
+++ b/data/model/legacy.py
@@ -1110,6 +1110,7 @@ def find_child_image(repo, parent_image, command):
                 .switch(Image)
                 .where(Image.ancestors % '%/' + parent_image.id + '/%',
                        ImageStorage.command == command)
+                .order_by(ImageStorage.created.desc())
                 .get())
   except Image.DoesNotExist:
     return None

From 6b9464c99996b52cc5d2380a42d3804740785d21 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Mon, 9 Feb 2015 16:59:21 -0500
Subject: [PATCH 11/19] Add support for 0.3 (the new builder version)

---
 buildman/component/buildcomponent.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index f7e2ff253..dc66dcfa1 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -19,7 +19,7 @@ HEARTBEAT_DELTA = datetime.timedelta(seconds=30)
 HEARTBEAT_TIMEOUT = 10
 INITIAL_TIMEOUT = 25
 
-SUPPORTED_WORKER_VERSIONS = ['0.2']
+SUPPORTED_WORKER_VERSIONS = ['0.2', '0.3']
 
 logger = logging.getLogger(__name__)
 

From 98b4f62ef7ab40420d993274d4e7bec9d99208b0 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Tue, 10 Feb 2015 15:43:01 -0500
Subject: [PATCH 12/19] Switch to using a squashed image for the build workers

---
 buildman/manager/executor.py        |  3 ++-
 buildman/templates/cloudconfig.yaml | 25 ++++++++++---------------
 requirements-nover.txt              |  1 +
 requirements.txt                    |  1 +
 4 files changed, 14 insertions(+), 16 deletions(-)

diff --git a/buildman/manager/executor.py b/buildman/manager/executor.py
index 92641c6ce..035d5cdf8 100644
--- a/buildman/manager/executor.py
+++ b/buildman/manager/executor.py
@@ -11,6 +11,7 @@ from trollius import coroutine, From, Return, get_event_loop
 from functools import partial
 
 from buildman.asyncutil import AsyncWrapper
+from container_cloud_config import CloudConfigContext
 
 
 logger = logging.getLogger(__name__)
@@ -20,7 +21,7 @@ ONE_HOUR = 60*60
 
 ENV = Environment(loader=FileSystemLoader('buildman/templates'))
 TEMPLATE = ENV.get_template('cloudconfig.yaml')
-
+CloudConfigContext().populate_jinja_environment(ENV)
 
 class ExecutorException(Exception):
   """ Exception raised when there is a problem starting or stopping a builder.
diff --git a/buildman/templates/cloudconfig.yaml b/buildman/templates/cloudconfig.yaml
index 13e6894bf..51bb2f090 100644
--- a/buildman/templates/cloudconfig.yaml
+++ b/buildman/templates/cloudconfig.yaml
@@ -19,18 +19,13 @@ coreos:
     group: {{ coreos_channel }}
 
   units:
-    - name: quay-builder.service
-      command: start
-      content: |
-        [Unit]
-        Description=Quay builder container
-        Author=Jake Moshenko
-        After=docker.service
-
-        [Service]
-        TimeoutStartSec=600
-        TimeoutStopSec=2000
-        ExecStartPre=/usr/bin/docker login -u {{ quay_username }} -p {{ quay_password }} -e unused quay.io
-        ExecStart=/usr/bin/docker run --rm --net=host --name quay-builder --privileged --env-file /root/overrides.list -v /var/run/docker.sock:/var/run/docker.sock -v /usr/share/ca-certificates:/etc/ssl/certs quay.io/coreos/registry-build-worker:{{ worker_tag }}
-        ExecStop=/usr/bin/docker stop quay-builder
-        ExecStopPost=/bin/sh -xc "/bin/sleep 120; /usr/bin/systemctl --no-block poweroff"
+    {{ dockersystemd('quay-builder',
+                     'quay.io/coreos/registry-build-worker',
+                     quay_username,
+                     quay_password,
+                     worker_tag,
+                     extra_args='--net=host --privileged --env-file /root/overrides.list -v /var/run/docker.sock:/var/run/docker.sock -v /usr/share/ca-certificates:/etc/ssl/certs',
+                     exec_stop_post=['/bin/sh -xc "/bin/sleep 120; /usr/bin/systemctl --no-block poweroff"'],
+                     flattened=True,
+                     restart_policy='no'
+                    ) | indent(4) }}
diff --git a/requirements-nover.txt b/requirements-nover.txt
index 3ac8c84a6..83953b6be 100644
--- a/requirements-nover.txt
+++ b/requirements-nover.txt
@@ -40,6 +40,7 @@ git+https://github.com/DevTable/aniso8601-fake.git
 git+https://github.com/DevTable/anunidecode.git
 git+https://github.com/DevTable/avatar-generator.git
 git+https://github.com/DevTable/pygithub.git
+git+https://github.com/DevTable/container-cloud-config.git
 git+https://github.com/jplana/python-etcd.git
 gipc
 pygpgme
diff --git a/requirements.txt b/requirements.txt
index 73ce4da45..7981d1c2b 100644
--- a/requirements.txt
+++ b/requirements.txt
@@ -63,5 +63,6 @@ git+https://github.com/DevTable/aniso8601-fake.git
 git+https://github.com/DevTable/anunidecode.git
 git+https://github.com/DevTable/avatar-generator.git
 git+https://github.com/DevTable/pygithub.git
+git+https://github.com/DevTable/container-cloud-config.git
 git+https://github.com/NateFerrero/oauth2lib.git
 git+https://github.com/jplana/python-etcd.git

From 3abb5bf0a3bc3226a1d7607ab7c639210019cacc Mon Sep 17 00:00:00 2001
From: Jimmy Zelinskie <jimmy.zelinskie@coreos.com>
Date: Tue, 10 Feb 2015 15:48:27 -0500
Subject: [PATCH 13/19] nginx: set proxy_buffer_size to 6MB

Because tags are included in our sessions, pushes containing many tags
will make our headers larger than the buffer nginx uses to send to the
client and then nginx is unable to validate the headers.
---
 conf/proxy-server-base.conf | 1 +
 conf/server-base.conf       | 1 +
 2 files changed, 2 insertions(+)

diff --git a/conf/proxy-server-base.conf b/conf/proxy-server-base.conf
index fb2f3f962..5bee725cf 100644
--- a/conf/proxy-server-base.conf
+++ b/conf/proxy-server-base.conf
@@ -13,6 +13,7 @@ proxy_set_header X-Forwarded-For $proxy_protocol_addr;
 proxy_set_header X-Forwarded-Proto $scheme;
 proxy_set_header Host $http_host;
 proxy_redirect off;
+proxy_buffer_size 6m;
 
 proxy_set_header Transfer-Encoding $http_transfer_encoding;
 
diff --git a/conf/server-base.conf b/conf/server-base.conf
index d5b211c52..6ac4dfb28 100644
--- a/conf/server-base.conf
+++ b/conf/server-base.conf
@@ -16,6 +16,7 @@ proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
 proxy_set_header X-Forwarded-Proto $scheme;
 proxy_set_header Host $http_host;
 proxy_redirect off;
+proxy_buffer_size 6m;
 
 proxy_set_header Transfer-Encoding $http_transfer_encoding;
 

From 893ae46dec6b7114504fd41252890ddb461bf205 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Tue, 10 Feb 2015 21:46:58 -0500
Subject: [PATCH 14/19] Add an ImageTree class and change to searching *all
 applicable* branches when looking for the best cache tag.

---
 buildman/jobutil/buildjob.py    |  41 ++++++-------
 buildman/jobutil/buildstatus.py |   8 +++
 test/test_imagetree.py          |  96 +++++++++++++++++++++++++++++
 util/imagetree.py               | 103 ++++++++++++++++++++++++++++++++
 4 files changed, 228 insertions(+), 20 deletions(-)
 create mode 100644 test/test_imagetree.py
 create mode 100644 util/imagetree.py

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index bcf2c33c2..46dab931c 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -4,6 +4,7 @@ import logging
 from cachetools import lru_cache
 from endpoints.notificationhelper import spawn_notification
 from data import model
+from util.imagetree import ImageTree
 
 logger = logging.getLogger(__name__)
 
@@ -91,31 +92,31 @@ class BuildJob(object):
     repo_namespace = repo_build.repository.namespace_user.username
     repo_name = repo_build.repository.name
 
-    current_image = model.get_image(repo_build.repository, base_image_id)
-    next_image = None
-    if current_image is None:
+    base_image = model.get_image(repo_build.repository, base_image_id)
+    if base_image is None:
       return None
 
-    # For each cache comment, find a child image that matches the command.
-    for cache_command in cache_commands:
-      full_command = '["/bin/sh", "-c", "%s"]' % cache_command
-      next_image = model.find_child_image(repo_build.repository, current_image, full_command)
-      if next_image is None:
-        break
+    # Build an in-memory tree of the full heirarchy of images in the repository.
+    all_images = model.get_repository_images(repo_namespace, repo_name)
+    all_tags = model.list_repository_tags(repo_namespace, repo_name)
+    tree = ImageTree(all_images, all_tags, base_filter=base_image.id)
 
-      current_image = next_image
-      logger.debug('Found cached image %s for comment %s', current_image.id, full_command)
+    # Find a path in the tree, starting at the base image, that matches the cache comments
+    # or some subset thereof.
+    def checker(step, image):
+      if step >= len(cache_commands):
+        return False
 
-    # Find a tag associated with the image, if any.
-    # TODO(jschorr): We should just return the image ID instead of a parent tag, OR we should
-    # make this more efficient.
-    for tag in model.list_repository_tags(repo_namespace, repo_name):
-      tag_image = tag.image
-      ancestor_index = '/%s/' % current_image.id
-      if ancestor_index in tag_image.ancestors or tag_image.id == current_image.id:
-        return tag.name
+      full_command = '["/bin/sh", "-c", "%s"]' % cache_commands[step]
+      return image.storage.comment == full_command
+
+    path = tree.find_longest_path(base_image.id, checker)
+    if not path:
+      return None
+
+    # Find any tag associated with the last image in the path.
+    return tree.tag_containing_images(path[-1])
 
-    return None
 
   def _determine_cached_tag_by_tag(self):
     """ Determines the cached tag by looking for one of the tags being built, and seeing if it
diff --git a/buildman/jobutil/buildstatus.py b/buildman/jobutil/buildstatus.py
index 393ecd3b4..2ae127ee0 100644
--- a/buildman/jobutil/buildstatus.py
+++ b/buildman/jobutil/buildstatus.py
@@ -7,6 +7,7 @@ class StatusHandler(object):
 
   def __init__(self, build_logs, repository_build_uuid):
     self._current_phase = None
+    self._current_command = None
     self._uuid = repository_build_uuid
     self._build_logs = build_logs
 
@@ -26,9 +27,16 @@ class StatusHandler(object):
     self._build_logs.append_log_message(self._uuid, log_message, log_type, log_data)
 
   def append_log(self, log_message, extra_data=None):
+    if log_message is None:
+      return
+
     self._append_log_message(log_message, log_data=extra_data)
 
   def set_command(self, command, extra_data=None):
+    if self._current_command == command:
+      return
+
+    self._current_command = command
     self._append_log_message(command, self._build_logs.COMMAND, extra_data)
 
   def set_error(self, error_message, extra_data=None, internal_error=False):
diff --git a/test/test_imagetree.py b/test/test_imagetree.py
new file mode 100644
index 000000000..824709be9
--- /dev/null
+++ b/test/test_imagetree.py
@@ -0,0 +1,96 @@
+import unittest
+
+from app import app
+from util.imagetree import ImageTree
+from initdb import setup_database_for_testing, finished_database_for_testing
+from data import model
+
+NAMESPACE = 'devtable'
+SIMPLE_REPO = 'simple'
+COMPLEX_REPO = 'complex'
+
+class TestImageTree(unittest.TestCase):
+  def setUp(self):
+    setup_database_for_testing(self)
+    self.app = app.test_client()
+    self.ctx = app.test_request_context()
+    self.ctx.__enter__()
+
+  def tearDown(self):
+    finished_database_for_testing(self)
+    self.ctx.__exit__(True, None, None)
+
+  def _get_base_image(self, all_images):
+    for image in all_images:
+      if image.ancestors == '/':
+        return image
+
+    return None
+
+  def test_longest_path_simple_repo(self):
+    all_images = list(model.get_repository_images(NAMESPACE, SIMPLE_REPO))
+    all_tags = list(model.list_repository_tags(NAMESPACE, SIMPLE_REPO))
+    tree = ImageTree(all_images, all_tags)
+
+    base_image = self._get_base_image(all_images)
+    tag_image = all_tags[0].image
+
+    def checker(index, image):
+      return True
+
+    ancestors = tag_image.ancestors.split('/')[2:-1] # Skip the first image.
+    result = tree.find_longest_path(base_image.id, checker)
+    self.assertEquals(3, len(result))
+    for index in range(0, 2):
+      self.assertEquals(int(ancestors[index]), result[index].id)
+
+    self.assertEquals('latest', tree.tag_containing_image(result[-1]))
+
+  def test_longest_path_complex_repo(self):
+    all_images = list(model.get_repository_images(NAMESPACE, COMPLEX_REPO))
+    all_tags = list(model.list_repository_tags(NAMESPACE, COMPLEX_REPO))
+    tree = ImageTree(all_images, all_tags)
+
+    base_image = self._get_base_image(all_images)
+
+    def checker(index, image):
+      return True
+
+    result = tree.find_longest_path(base_image.id, checker)
+    self.assertEquals(4, len(result))
+    self.assertEquals('v2.0', tree.tag_containing_image(result[-1]))
+
+  def test_filtering(self):
+    all_images = list(model.get_repository_images(NAMESPACE, COMPLEX_REPO))
+    all_tags = list(model.list_repository_tags(NAMESPACE, COMPLEX_REPO))
+    tree = ImageTree(all_images, all_tags, parent_filter=1245)
+
+    base_image = self._get_base_image(all_images)
+
+    def checker(index, image):
+      return True
+
+    result = tree.find_longest_path(base_image.id, checker)
+    self.assertEquals(0, len(result))
+
+  def test_find_tag_parent_image(self):
+    all_images = list(model.get_repository_images(NAMESPACE, COMPLEX_REPO))
+    all_tags = list(model.list_repository_tags(NAMESPACE, COMPLEX_REPO))
+    tree = ImageTree(all_images, all_tags)
+
+    base_image = self._get_base_image(all_images)
+
+    def checker(index, image):
+      return True
+
+    result = tree.find_longest_path(base_image.id, checker)
+    self.assertEquals(4, len(result))
+
+    # Only use the first two images. They don't have tags, but the method should
+    # still return the tag that contains them.
+    self.assertEquals('v2.0', tree.tag_containing_image(result[0]))
+
+
+if __name__ == '__main__':
+  unittest.main()
+
diff --git a/util/imagetree.py b/util/imagetree.py
new file mode 100644
index 000000000..39cd5c3c9
--- /dev/null
+++ b/util/imagetree.py
@@ -0,0 +1,103 @@
+class ImageTreeNode(object):
+  """ A node in the image tree. """
+  def __init__(self, image):
+    self.image = image
+    self.parent = None
+    self.children = []
+    self.tags = []
+
+  def add_child(self, child):
+    self.children.append(child)
+    child.parent = self
+
+  def add_tag(self, tag):
+    self.tags.append(tag)
+
+
+class ImageTree(object):
+  """ In-memory tree for easy traversal and lookup of images in a repository. """
+
+  def __init__(self, all_images, all_tags, base_filter=None):
+    self._tag_map = {}
+    self._image_map = {}
+
+    self._build(all_images, all_tags, base_filter)
+
+  def _build(self,  all_images, all_tags, base_filter=None):
+    # Build nodes for each of the images.
+    for image in all_images:
+      ancestors = image.ancestors.split('/')[1:-1]
+
+      # Filter any unneeded images.
+      if base_filter is not None:
+        if image.id != base_filter and not str(base_filter) in ancestors:
+          continue
+
+      self._image_map[image.id] = ImageTreeNode(image)
+
+    # Connect the nodes to their parents.
+    for image_node in self._image_map.values():
+      image = image_node.image
+      parent_image_id = image.ancestors.split('/')[-2] if image.ancestors else None
+      if not parent_image_id:
+        continue
+
+      parent_node = self._image_map.get(int(parent_image_id))
+      if parent_node is not None:
+        parent_node.add_child(image_node)
+
+    # Build the tag map.
+    for tag in all_tags:
+      image_node = self._image_map.get(tag.image.id)
+      if not image_node:
+        continue
+
+      self._tag_map = image_node
+      image_node.add_tag(tag.name)
+
+
+  def find_longest_path(self, image_id, checker):
+    """ Returns a list of images representing the longest path that matches the given
+        checker function, starting from the given image_id *exclusive*.
+    """
+    start_node = self._image_map.get(image_id)
+    if not start_node:
+      return []
+
+    return self._find_longest_path(start_node, checker, -1)[1:]
+
+
+  def _find_longest_path(self, image_node, checker, index):
+    found_path = []
+
+    for child_node in image_node.children:
+      if not checker(index + 1, child_node.image):
+        continue
+
+      found = self._find_longest_path(child_node, checker, index + 1)
+      if found and len(found) > len(found_path):
+        found_path = found
+
+    return [image_node.image] + found_path
+
+
+  def tag_containing_image(self, image):
+    """ Returns the name of the closest tag containing the given image. """
+    if not image:
+      return None
+
+    # Check the current image for a tag.
+    image_node = self._image_map.get(image.id)
+    if image_node is None:
+      return None
+
+    if image_node.tags:
+      return image_node.tags[0]
+
+    # Check any deriving images for a tag.
+    for child_node in image_node.children:
+      found = self.tag_containing_image(child_node.image)
+      if found is not None:
+        return found
+
+    return None
\ No newline at end of file

From f8a917ec26d57c239f8be871b9b3518f5ef4cb19 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Tue, 10 Feb 2015 22:02:39 -0500
Subject: [PATCH 15/19] Fix test

---
 test/test_imagetree.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/test_imagetree.py b/test/test_imagetree.py
index 824709be9..d72eb6505 100644
--- a/test/test_imagetree.py
+++ b/test/test_imagetree.py
@@ -63,7 +63,7 @@ class TestImageTree(unittest.TestCase):
   def test_filtering(self):
     all_images = list(model.get_repository_images(NAMESPACE, COMPLEX_REPO))
     all_tags = list(model.list_repository_tags(NAMESPACE, COMPLEX_REPO))
-    tree = ImageTree(all_images, all_tags, parent_filter=1245)
+    tree = ImageTree(all_images, all_tags, base_filter=1245)
 
     base_image = self._get_base_image(all_images)
 

From 0f3d87466e6b7b1732d5ff820241db7882f15983 Mon Sep 17 00:00:00 2001
From: Jake Moshenko <jake.moshenko@coreos.com>
Date: Wed, 11 Feb 2015 14:15:18 -0500
Subject: [PATCH 16/19] Unify the logging infrastructure and turn the prod
 logging level to INFO in preparation for picking up a new cloud logger.

---
 app.py                   | 14 +++---
 application.py           |  2 +-
 conf/gunicorn_local.py   |  2 +-
 conf/logging.conf        | 32 +-------------
 conf/logging_debug.conf  | 21 +++++++++
 endpoints/common.py      |  3 +-
 endpoints/index.py       | 39 ++++++++---------
 endpoints/registry.py    | 95 ++++++++++++++++++++--------------------
 endpoints/trackhelper.py | 13 +++---
 9 files changed, 105 insertions(+), 116 deletions(-)
 create mode 100644 conf/logging_debug.conf

diff --git a/app.py b/app.py
index ae7f95600..a94b8d061 100644
--- a/app.py
+++ b/app.py
@@ -3,7 +3,7 @@ import os
 import json
 import yaml
 
-from flask import Flask as BaseFlask, Config as BaseConfig, request, Request
+from flask import Flask as BaseFlask, Config as BaseConfig, request, Request, _request_ctx_stack
 from flask.ext.principal import Principal
 from flask.ext.login import LoginManager, UserMixin
 from flask.ext.mail import Mail
@@ -65,7 +65,6 @@ LICENSE_FILENAME = 'conf/stack/license.enc'
 
 app = Flask(__name__)
 logger = logging.getLogger(__name__)
-profile = logging.getLogger('profile')
 
 
 if 'TEST' in os.environ:
@@ -101,21 +100,24 @@ class RequestWithId(Request):
 
 @app.before_request
 def _request_start():
-  profile.debug('Starting request: %s', request.path)
+  logger.debug('Starting request: %s', request.path)
 
 
 @app.after_request
 def _request_end(r):
-  profile.debug('Ending request: %s', request.path)
+  logger.debug('Ending request: %s', request.path)
   return r
 
 
 class InjectingFilter(logging.Filter):
   def filter(self, record):
-    record.msg = '[%s] %s' % (request.request_id, record.msg)
+    if _request_ctx_stack.top is not None:
+      record.msg = '[%s] %s' % (request.request_id, record.msg)
     return True
 
-profile.addFilter(InjectingFilter())
+# Add the request id filter to all handlers of the root logger
+for handler in logging.getLogger().handlers:
+  handler.addFilter(InjectingFilter())
 
 app.request_class = RequestWithId
 
diff --git a/application.py b/application.py
index a9bd0df6e..235a80b16 100644
--- a/application.py
+++ b/application.py
@@ -11,5 +11,5 @@ import registry
 
 
 if __name__ == '__main__':
-  logging.config.fileConfig('conf/logging.conf', disable_existing_loggers=False)
+  logging.config.fileConfig('conf/logging_debug.conf', disable_existing_loggers=False)
   application.run(port=5000, debug=True, threaded=True, host='0.0.0.0')
diff --git a/conf/gunicorn_local.py b/conf/gunicorn_local.py
index aa16e63ec..ce93304b0 100644
--- a/conf/gunicorn_local.py
+++ b/conf/gunicorn_local.py
@@ -3,5 +3,5 @@ workers = 2
 worker_class = 'gevent'
 timeout = 2000
 daemon = False
-logconfig = 'conf/logging.conf'
+logconfig = 'conf/logging_debug.conf'
 pythonpath = '.'
diff --git a/conf/logging.conf b/conf/logging.conf
index d009f08ee..317803a24 100644
--- a/conf/logging.conf
+++ b/conf/logging.conf
@@ -1,5 +1,5 @@
 [loggers]
-keys=root, gunicorn.error, gunicorn.access, application.profiler, boto, werkzeug
+keys=root
 
 [handlers]
 keys=console
@@ -7,39 +7,9 @@ keys=console
 [formatters]
 keys=generic
 
-[logger_application.profiler]
-level=DEBUG
-handlers=console
-propagate=0
-qualname=application.profiler
-
 [logger_root]
-level=DEBUG
-handlers=console
-
-[logger_boto]
 level=INFO
 handlers=console
-propagate=0
-qualname=boto
-
-[logger_werkzeug]
-level=DEBUG
-handlers=console
-propagate=0
-qualname=werkzeug
-
-[logger_gunicorn.error]
-level=INFO
-handlers=console
-propagate=1
-qualname=gunicorn.error
-
-[logger_gunicorn.access]
-level=INFO
-handlers=console
-propagate=0
-qualname=gunicorn.access
 
 [handler_console]
 class=StreamHandler
diff --git a/conf/logging_debug.conf b/conf/logging_debug.conf
new file mode 100644
index 000000000..01a3c8fbb
--- /dev/null
+++ b/conf/logging_debug.conf
@@ -0,0 +1,21 @@
+[loggers]
+keys=root
+
+[handlers]
+keys=console
+
+[formatters]
+keys=generic
+
+[logger_root]
+level=DEBUG
+handlers=console
+
+[handler_console]
+class=StreamHandler
+formatter=generic
+args=(sys.stdout, )
+
+[formatter_generic]
+format=%(asctime)s [%(process)d] [%(levelname)s] [%(name)s] %(message)s
+class=logging.Formatter
diff --git a/endpoints/common.py b/endpoints/common.py
index 3534ee072..9301329e0 100644
--- a/endpoints/common.py
+++ b/endpoints/common.py
@@ -29,7 +29,6 @@ from endpoints.notificationhelper import spawn_notification
 import features
 
 logger = logging.getLogger(__name__)
-profile = logging.getLogger('application.profiler')
 
 route_data = None
 
@@ -253,7 +252,7 @@ def start_build(repository, dockerfile_id, tags, build_name, subdir, manual,
                    metadata=metadata, repository=repository)
 
   # Add notifications for the build queue.
-  profile.debug('Adding notifications for repository')
+  logger.debug('Adding notifications for repository')
   event_data = {
     'build_id': build_request.uuid,
     'build_name': build_name,
diff --git a/endpoints/index.py b/endpoints/index.py
index de45f2fde..660ab94aa 100644
--- a/endpoints/index.py
+++ b/endpoints/index.py
@@ -23,7 +23,6 @@ from endpoints.notificationhelper import spawn_notification
 import features
 
 logger = logging.getLogger(__name__)
-profile = logging.getLogger('application.profiler')
 
 index = Blueprint('index', __name__)
 
@@ -120,7 +119,7 @@ def create_user():
 
   else:
     # New user case
-    profile.debug('Creating user')
+    logger.debug('Creating user')
     new_user = None
 
     try:
@@ -128,10 +127,10 @@ def create_user():
     except model.TooManyUsersException as ex:
       abort(402, 'Seat limit has been reached for this license', issue='seat-limit')
 
-    profile.debug('Creating email code for user')
+    logger.debug('Creating email code for user')
     code = model.create_confirm_email_code(new_user)
 
-    profile.debug('Sending email code to user')
+    logger.debug('Sending email code to user')
     send_confirmation_email(new_user.username, new_user.email, code.code)
 
     return make_response('Created', 201)
@@ -168,12 +167,12 @@ def update_user(username):
     update_request = request.get_json()
 
     if 'password' in update_request:
-      profile.debug('Updating user password')
+      logger.debug('Updating user password')
       model.change_password(get_authenticated_user(),
                             update_request['password'])
 
     if 'email' in update_request:
-      profile.debug('Updating user email')
+      logger.debug('Updating user email')
       model.update_email(get_authenticated_user(), update_request['email'])
 
     return jsonify({
@@ -189,13 +188,13 @@ def update_user(username):
 @parse_repository_name
 @generate_headers(role='write')
 def create_repository(namespace, repository):
-  profile.debug('Parsing image descriptions')
+  logger.debug('Parsing image descriptions')
   image_descriptions = json.loads(request.data.decode('utf8'))
 
-  profile.debug('Looking up repository')
+  logger.debug('Looking up repository')
   repo = model.get_repository(namespace, repository)
 
-  profile.debug('Repository looked up')
+  logger.debug('Repository looked up')
   if not repo and get_authenticated_user() is None:
     logger.debug('Attempt to create new repository without user auth.')
     abort(401,
@@ -219,11 +218,11 @@ def create_repository(namespace, repository):
             issue='no-create-permission',
             namespace=namespace)
 
-    profile.debug('Creaing repository with owner: %s', get_authenticated_user().username)
+    logger.debug('Creaing repository with owner: %s', get_authenticated_user().username)
     repo = model.create_repository(namespace, repository,
                                    get_authenticated_user())
 
-  profile.debug('Determining already added images')
+  logger.debug('Determining already added images')
   added_images = OrderedDict([(desc['id'], desc) for desc in image_descriptions])
   new_repo_images = dict(added_images)
 
@@ -239,7 +238,7 @@ def create_repository(namespace, repository):
     for existing in existing_images:
       added_images.pop(existing.docker_image_id)
 
-  profile.debug('Creating/Linking necessary images')
+  logger.debug('Creating/Linking necessary images')
   username = get_authenticated_user() and get_authenticated_user().username
   translations = {}
   for image_description in added_images.values():
@@ -247,7 +246,7 @@ def create_repository(namespace, repository):
                                     translations, storage.preferred_locations[0])
 
 
-  profile.debug('Created images')
+  logger.debug('Created images')
   track_and_log('push_repo', repo)
   return make_response('Created', 201)
 
@@ -260,14 +259,14 @@ def update_images(namespace, repository):
   permission = ModifyRepositoryPermission(namespace, repository)
 
   if permission.can():
-    profile.debug('Looking up repository')
+    logger.debug('Looking up repository')
     repo = model.get_repository(namespace, repository)
     if not repo:
       # Make sure the repo actually exists.
       abort(404, message='Unknown repository', issue='unknown-repo')
 
     if get_authenticated_user():
-      profile.debug('Publishing push event')
+      logger.debug('Publishing push event')
       username = get_authenticated_user().username
 
       # Mark that the user has pushed the repo.
@@ -280,11 +279,11 @@ def update_images(namespace, repository):
       event = userevents.get_event(username)
       event.publish_event_data('docker-cli', user_data)
 
-    profile.debug('GCing repository')
+    logger.debug('GCing repository')
     num_removed = model.garbage_collect_repository(namespace, repository)
 
     # Generate a job for each notification that has been added to this repo
-    profile.debug('Adding notifications for repository')
+    logger.debug('Adding notifications for repository')
 
     updated_tags = session.get('pushed_tags', {})
     event_data = {
@@ -307,13 +306,13 @@ def get_repository_images(namespace, repository):
   # TODO invalidate token?
   if permission.can() or model.repository_is_public(namespace, repository):
     # We can't rely on permissions to tell us if a repo exists anymore
-    profile.debug('Looking up repository')
+    logger.debug('Looking up repository')
     repo = model.get_repository(namespace, repository)
     if not repo:
       abort(404, message='Unknown repository', issue='unknown-repo')
 
     all_images = []
-    profile.debug('Retrieving repository images')
+    logger.debug('Retrieving repository images')
     for image in model.get_repository_images(namespace, repository):
       new_image_view = {
         'id': image.docker_image_id,
@@ -321,7 +320,7 @@ def get_repository_images(namespace, repository):
       }
       all_images.append(new_image_view)
 
-    profile.debug('Building repository image response')
+    logger.debug('Building repository image response')
     resp = make_response(json.dumps(all_images), 200)
     resp.mimetype = 'application/json'
 
diff --git a/endpoints/registry.py b/endpoints/registry.py
index b4b03334f..5178f3a83 100644
--- a/endpoints/registry.py
+++ b/endpoints/registry.py
@@ -20,7 +20,6 @@ from util import gzipstream
 registry = Blueprint('registry', __name__)
 
 logger = logging.getLogger(__name__)
-profile = logging.getLogger('application.profiler')
 
 class SocketReader(object):
   def __init__(self, fp):
@@ -100,12 +99,12 @@ def set_cache_headers(f):
 def head_image_layer(namespace, repository, image_id, headers):
   permission = ReadRepositoryPermission(namespace, repository)
 
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   if permission.can() or model.repository_is_public(namespace, repository):
-    profile.debug('Looking up repo image')
+    logger.debug('Looking up repo image')
     repo_image = model.get_repo_image_extended(namespace, repository, image_id)
     if not repo_image:
-      profile.debug('Image not found')
+      logger.debug('Image not found')
       abort(404, 'Image %(image_id)s not found', issue='unknown-image',
             image_id=image_id)
 
@@ -114,7 +113,7 @@ def head_image_layer(namespace, repository, image_id, headers):
     # Add the Accept-Ranges header if the storage engine supports resumable
     # downloads.
     if store.get_supports_resumable_downloads(repo_image.storage.locations):
-      profile.debug('Storage supports resumable downloads')
+      logger.debug('Storage supports resumable downloads')
       extra_headers['Accept-Ranges'] = 'bytes'
 
     resp = make_response('')
@@ -133,35 +132,35 @@ def head_image_layer(namespace, repository, image_id, headers):
 def get_image_layer(namespace, repository, image_id, headers):
   permission = ReadRepositoryPermission(namespace, repository)
 
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   if permission.can() or model.repository_is_public(namespace, repository):
-    profile.debug('Looking up repo image')
+    logger.debug('Looking up repo image')
     repo_image = model.get_repo_image_extended(namespace, repository, image_id)
     if not repo_image:
-      profile.debug('Image not found')
+      logger.debug('Image not found')
       abort(404, 'Image %(image_id)s not found', issue='unknown-image',
             image_id=image_id)
 
-    profile.debug('Looking up the layer path')
+    logger.debug('Looking up the layer path')
     try:
       path = store.image_layer_path(repo_image.storage.uuid)
 
-      profile.debug('Looking up the direct download URL')
+      logger.debug('Looking up the direct download URL')
       direct_download_url = store.get_direct_download_url(repo_image.storage.locations, path)
 
       if direct_download_url:
-        profile.debug('Returning direct download URL')
+        logger.debug('Returning direct download URL')
         resp = redirect(direct_download_url)
         return resp
 
-      profile.debug('Streaming layer data')
+      logger.debug('Streaming layer data')
 
       # Close the database handle here for this process before we send the long download.
       database.close_db_filter(None)
 
       return Response(store.stream_read(repo_image.storage.locations, path), headers=headers)
     except (IOError, AttributeError):
-      profile.exception('Image layer data not found')
+      logger.exception('Image layer data not found')
       abort(404, 'Image %(image_id)s not found', issue='unknown-image',
             image_id=image_id)
 
@@ -172,30 +171,30 @@ def get_image_layer(namespace, repository, image_id, headers):
 @process_auth
 @extract_namespace_repo_from_session
 def put_image_layer(namespace, repository, image_id):
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   permission = ModifyRepositoryPermission(namespace, repository)
   if not permission.can():
     abort(403)
 
-  profile.debug('Retrieving image')
+  logger.debug('Retrieving image')
   repo_image = model.get_repo_image_extended(namespace, repository, image_id)
   try:
-    profile.debug('Retrieving image data')
+    logger.debug('Retrieving image data')
     uuid = repo_image.storage.uuid
     json_data = store.get_content(repo_image.storage.locations, store.image_json_path(uuid))
   except (IOError, AttributeError):
-    profile.exception('Exception when retrieving image data')
+    logger.exception('Exception when retrieving image data')
     abort(404, 'Image %(image_id)s not found', issue='unknown-image',
           image_id=image_id)
 
-  profile.debug('Retrieving image path info')
+  logger.debug('Retrieving image path info')
   layer_path = store.image_layer_path(uuid)
 
   if (store.exists(repo_image.storage.locations, layer_path) and not
       image_is_uploading(repo_image)):
     exact_abort(409, 'Image already exists')
 
-  profile.debug('Storing layer data')
+  logger.debug('Storing layer data')
 
   input_stream = request.stream
   if request.headers.get('transfer-encoding') == 'chunked':
@@ -262,7 +261,7 @@ def put_image_layer(namespace, repository, image_id):
 
   # The layer is ready for download, send a job to the work queue to
   # process it.
-  profile.debug('Adding layer to diff queue')
+  logger.debug('Adding layer to diff queue')
   repo = model.get_repository(namespace, repository)
   image_diff_queue.put([repo.namespace_user.username, repository, image_id], json.dumps({
     'namespace_user_id': repo.namespace_user.id,
@@ -277,7 +276,7 @@ def put_image_layer(namespace, repository, image_id):
 @process_auth
 @extract_namespace_repo_from_session
 def put_image_checksum(namespace, repository, image_id):
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   permission = ModifyRepositoryPermission(namespace, repository)
   if not permission.can():
     abort(403)
@@ -303,23 +302,23 @@ def put_image_checksum(namespace, repository, image_id):
     abort(400, 'Checksum not found in Cookie for image %(image_id)s',
           issue='missing-checksum-cookie', image_id=image_id)
 
-  profile.debug('Looking up repo image')
+  logger.debug('Looking up repo image')
   repo_image = model.get_repo_image_extended(namespace, repository, image_id)
   if not repo_image or not repo_image.storage:
     abort(404, 'Image not found: %(image_id)s', issue='unknown-image', image_id=image_id)
 
   uuid = repo_image.storage.uuid
 
-  profile.debug('Looking up repo layer data')
+  logger.debug('Looking up repo layer data')
   if not store.exists(repo_image.storage.locations, store.image_json_path(uuid)):
     abort(404, 'Image not found: %(image_id)s', issue='unknown-image', image_id=image_id)
 
-  profile.debug('Marking image path')
+  logger.debug('Marking image path')
   if not image_is_uploading(repo_image):
     abort(409, 'Cannot set checksum for image %(image_id)s',
           issue='image-write-error', image_id=image_id)
 
-  profile.debug('Storing image checksum')
+  logger.debug('Storing image checksum')
   err = store_checksum(repo_image.storage, checksum)
   if err:
     abort(400, err)
@@ -336,7 +335,7 @@ def put_image_checksum(namespace, repository, image_id):
 
   # The layer is ready for download, send a job to the work queue to
   # process it.
-  profile.debug('Adding layer to diff queue')
+  logger.debug('Adding layer to diff queue')
   repo = model.get_repository(namespace, repository)
   image_diff_queue.put([repo.namespace_user.username, repository, image_id], json.dumps({
     'namespace_user_id': repo.namespace_user.id,
@@ -353,23 +352,23 @@ def put_image_checksum(namespace, repository, image_id):
 @require_completion
 @set_cache_headers
 def get_image_json(namespace, repository, image_id, headers):
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   permission = ReadRepositoryPermission(namespace, repository)
   if not permission.can() and not model.repository_is_public(namespace,
                                                              repository):
     abort(403)
 
-  profile.debug('Looking up repo image')
+  logger.debug('Looking up repo image')
   repo_image = model.get_repo_image_extended(namespace, repository, image_id)
 
-  profile.debug('Looking up repo layer data')
+  logger.debug('Looking up repo layer data')
   try:
     uuid = repo_image.storage.uuid
     data = store.get_content(repo_image.storage.locations, store.image_json_path(uuid))
   except (IOError, AttributeError):
     flask_abort(404)
 
-  profile.debug('Looking up repo layer size')
+  logger.debug('Looking up repo layer size')
   size = repo_image.storage.image_size
   headers['X-Docker-Size'] = str(size)
 
@@ -384,16 +383,16 @@ def get_image_json(namespace, repository, image_id, headers):
 @require_completion
 @set_cache_headers
 def get_image_ancestry(namespace, repository, image_id, headers):
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   permission = ReadRepositoryPermission(namespace, repository)
   if not permission.can() and not model.repository_is_public(namespace,
                                                              repository):
     abort(403)
 
-  profile.debug('Looking up repo image')
+  logger.debug('Looking up repo image')
   repo_image = model.get_repo_image_extended(namespace, repository, image_id)
 
-  profile.debug('Looking up image data')
+  logger.debug('Looking up image data')
   try:
     uuid = repo_image.storage.uuid
     data = store.get_content(repo_image.storage.locations, store.image_ancestry_path(uuid))
@@ -401,11 +400,11 @@ def get_image_ancestry(namespace, repository, image_id, headers):
     abort(404, 'Image %(image_id)s not found', issue='unknown-image',
           image_id=image_id)
 
-  profile.debug('Converting to <-> from JSON')
+  logger.debug('Converting to <-> from JSON')
   response = make_response(json.dumps(json.loads(data)), 200)
   response.headers.extend(headers)
 
-  profile.debug('Done')
+  logger.debug('Done')
   return response
 
 
@@ -435,12 +434,12 @@ def store_checksum(image_storage, checksum):
 @process_auth
 @extract_namespace_repo_from_session
 def put_image_json(namespace, repository, image_id):
-  profile.debug('Checking repo permissions')
+  logger.debug('Checking repo permissions')
   permission = ModifyRepositoryPermission(namespace, repository)
   if not permission.can():
     abort(403)
 
-  profile.debug('Parsing image JSON')
+  logger.debug('Parsing image JSON')
   try:
     data = json.loads(request.data.decode('utf8'))
   except ValueError:
@@ -454,10 +453,10 @@ def put_image_json(namespace, repository, image_id):
     abort(400, 'Missing key `id` in JSON for image: %(image_id)s',
           issue='invalid-request', image_id=image_id)
 
-  profile.debug('Looking up repo image')
+  logger.debug('Looking up repo image')
   repo_image = model.get_repo_image_extended(namespace, repository, image_id)
   if not repo_image:
-    profile.debug('Image not found')
+    logger.debug('Image not found')
     abort(404, 'Image %(image_id)s not found', issue='unknown-image',
           image_id=image_id)
 
@@ -471,24 +470,24 @@ def put_image_json(namespace, repository, image_id):
 
   parent_image = None
   if parent_id:
-    profile.debug('Looking up parent image')
+    logger.debug('Looking up parent image')
     parent_image = model.get_repo_image_extended(namespace, repository, parent_id)
 
   parent_uuid = parent_image and parent_image.storage.uuid
   parent_locations = parent_image and parent_image.storage.locations
 
   if parent_id:
-    profile.debug('Looking up parent image data')
+    logger.debug('Looking up parent image data')
 
   if (parent_id and not
       store.exists(parent_locations, store.image_json_path(parent_uuid))):
     abort(400, 'Image %(image_id)s depends on non existing parent image %(parent_id)s',
           issue='invalid-request', image_id=image_id, parent_id=parent_id)
 
-  profile.debug('Looking up image storage paths')
+  logger.debug('Looking up image storage paths')
   json_path = store.image_json_path(uuid)
 
-  profile.debug('Checking if image already exists')
+  logger.debug('Checking if image already exists')
   if (store.exists(repo_image.storage.locations, json_path) and not
       image_is_uploading(repo_image)):
     exact_abort(409, 'Image already exists')
@@ -501,24 +500,24 @@ def put_image_json(namespace, repository, image_id):
   command_list = data.get('container_config', {}).get('Cmd', None)
   command = json.dumps(command_list) if command_list else None
 
-  profile.debug('Setting image metadata')
+  logger.debug('Setting image metadata')
   model.set_image_metadata(image_id, namespace, repository,
                            data.get('created'), data.get('comment'), command,
                            parent_image)
 
-  profile.debug('Putting json path')
+  logger.debug('Putting json path')
   store.put_content(repo_image.storage.locations, json_path, request.data)
 
-  profile.debug('Generating image ancestry')
+  logger.debug('Generating image ancestry')
 
   try:
     generate_ancestry(image_id, uuid, repo_image.storage.locations, parent_id, parent_uuid,
                       parent_locations)
   except IOError as ioe:
-    profile.debug('Error when generating ancestry: %s' % ioe.message)
+    logger.debug('Error when generating ancestry: %s' % ioe.message)
     abort(404)
 
-  profile.debug('Done')
+  logger.debug('Done')
   return make_response('true', 200)
 
 
diff --git a/endpoints/trackhelper.py b/endpoints/trackhelper.py
index 83b9d4270..fb99a2c2d 100644
--- a/endpoints/trackhelper.py
+++ b/endpoints/trackhelper.py
@@ -6,7 +6,6 @@ from flask import request
 from auth.auth_context import get_authenticated_user, get_validated_token, get_validated_oauth_token
 
 logger = logging.getLogger(__name__)
-profile = logging.getLogger('application.profiler')
 
 def track_and_log(event_name, repo, **kwargs):
   repository = repo.name
@@ -23,7 +22,7 @@ def track_and_log(event_name, repo, **kwargs):
   authenticated_user = get_authenticated_user()
   authenticated_token = get_validated_token() if not authenticated_user else None
 
-  profile.debug('Logging the %s to Mixpanel and the log system', event_name)
+  logger.debug('Logging the %s to Mixpanel and the log system', event_name)
   if authenticated_oauth_token:
     metadata['oauth_token_id'] = authenticated_oauth_token.id
     metadata['oauth_token_application_id'] = authenticated_oauth_token.application.client_id
@@ -45,9 +44,9 @@ def track_and_log(event_name, repo, **kwargs):
   }
 
   # Publish the user event (if applicable)
-  profile.debug('Checking publishing %s to the user events system', event_name)
+  logger.debug('Checking publishing %s to the user events system', event_name)
   if authenticated_user:
-    profile.debug('Publishing %s to the user events system', event_name)
+    logger.debug('Publishing %s to the user events system', event_name)
     user_event_data = {
       'action': event_name,
       'repository': repository,
@@ -58,14 +57,14 @@ def track_and_log(event_name, repo, **kwargs):
     event.publish_event_data('docker-cli', user_event_data)
 
   # Save the action to mixpanel.
-  profile.debug('Logging the %s to Mixpanel', event_name)
+  logger.debug('Logging the %s to Mixpanel', event_name)
   analytics.track(analytics_id, event_name, extra_params)
 
   # Log the action to the database.
-  profile.debug('Logging the %s to logs system', event_name)
+  logger.debug('Logging the %s to logs system', event_name)
   model.log_action(event_name, namespace,
                    performer=authenticated_user,
                    ip=request.remote_addr, metadata=metadata,
                    repository=repo)
 
-  profile.debug('Track and log of %s complete', event_name)
+  logger.debug('Track and log of %s complete', event_name)

From e1a15464a195d69720f938735ae5dabbc6723977 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Wed, 11 Feb 2015 16:02:36 -0500
Subject: [PATCH 17/19] Fix typo, add some logging and fix command comparison

---
 buildman/jobutil/buildjob.py | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/buildman/jobutil/buildjob.py b/buildman/jobutil/buildjob.py
index 46dab931c..1710c3aab 100644
--- a/buildman/jobutil/buildjob.py
+++ b/buildman/jobutil/buildjob.py
@@ -108,14 +108,17 @@ class BuildJob(object):
         return False
 
       full_command = '["/bin/sh", "-c", "%s"]' % cache_commands[step]
-      return image.storage.comment == full_command
+      logger.debug('Checking step #%s: %s, %s == %s', step, image.id,
+                   image.storage.command, full_command)
+
+      return image.storage.command == full_command
 
     path = tree.find_longest_path(base_image.id, checker)
     if not path:
       return None
 
     # Find any tag associated with the last image in the path.
-    return tree.tag_containing_images(path[-1])
+    return tree.tag_containing_image(path[-1])
 
 
   def _determine_cached_tag_by_tag(self):

From 42db22157635a269eca02dcdda16f919facdd7d3 Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Wed, 11 Feb 2015 16:25:09 -0500
Subject: [PATCH 18/19] Disable proxy server buffer changes

---
 conf/proxy-server-base.conf | 1 -
 conf/server-base.conf       | 1 -
 2 files changed, 2 deletions(-)

diff --git a/conf/proxy-server-base.conf b/conf/proxy-server-base.conf
index 5bee725cf..fb2f3f962 100644
--- a/conf/proxy-server-base.conf
+++ b/conf/proxy-server-base.conf
@@ -13,7 +13,6 @@ proxy_set_header X-Forwarded-For $proxy_protocol_addr;
 proxy_set_header X-Forwarded-Proto $scheme;
 proxy_set_header Host $http_host;
 proxy_redirect off;
-proxy_buffer_size 6m;
 
 proxy_set_header Transfer-Encoding $http_transfer_encoding;
 
diff --git a/conf/server-base.conf b/conf/server-base.conf
index 6ac4dfb28..d5b211c52 100644
--- a/conf/server-base.conf
+++ b/conf/server-base.conf
@@ -16,7 +16,6 @@ proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
 proxy_set_header X-Forwarded-Proto $scheme;
 proxy_set_header Host $http_host;
 proxy_redirect off;
-proxy_buffer_size 6m;
 
 proxy_set_header Transfer-Encoding $http_transfer_encoding;
 

From f796c281d576f49192219a6d2893134ffea7a4bb Mon Sep 17 00:00:00 2001
From: Joseph Schorr <joseph.schorr@coreos.com>
Date: Wed, 11 Feb 2015 17:12:53 -0500
Subject: [PATCH 19/19] Remove support for v0.2

---
 buildman/component/buildcomponent.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/buildman/component/buildcomponent.py b/buildman/component/buildcomponent.py
index dc66dcfa1..72caec215 100644
--- a/buildman/component/buildcomponent.py
+++ b/buildman/component/buildcomponent.py
@@ -19,7 +19,7 @@ HEARTBEAT_DELTA = datetime.timedelta(seconds=30)
 HEARTBEAT_TIMEOUT = 10
 INITIAL_TIMEOUT = 25
 
-SUPPORTED_WORKER_VERSIONS = ['0.2', '0.3']
+SUPPORTED_WORKER_VERSIONS = ['0.3']
 
 logger = logging.getLogger(__name__)