import logging import daemon import argparse import os import requests import re import json import shutil import tarfile from docker import Client from docker.errors import APIError from tempfile import TemporaryFile, mkdtemp from zipfile import ZipFile from functools import partial from datetime import datetime, timedelta from threading import Event from uuid import uuid4 from collections import defaultdict from data.queue import dockerfile_build_queue from data import model from workers.worker import Worker from app import app, userfiles as user_files from util.safetar import safe_extractall from util.dockerfileparse import parse_dockerfile, ParsedDockerfile, serialize_dockerfile root_logger = logging.getLogger('') root_logger.setLevel(logging.DEBUG) FORMAT = '%(asctime)-15s - %(levelname)s - %(pathname)s - %(funcName)s - %(message)s' formatter = logging.Formatter(FORMAT) logger = logging.getLogger(__name__) build_logs = app.config['BUILDLOGS'] TIMEOUT_PERIOD_MINUTES = 20 CACHE_EXPIRATION_PERIOD_HOURS = 24 NO_TAGS = [':'] class StatusWrapper(object): def __init__(self, build_uuid): self._uuid = build_uuid self._status = { 'total_commands': None, 'current_command': None, 'push_completion': 0.0, 'pull_completion': 0.0, } self.__exit__(None, None, None) def __enter__(self): return self._status def __exit__(self, exc_type, value, traceback): build_logs.set_status(self._uuid, self._status) class _IncompleteJsonError(Exception): def __init__(self, start_from): self.start_from = start_from class _StreamingJSONDecoder(json.JSONDecoder): FLAGS = re.VERBOSE | re.MULTILINE | re.DOTALL WHITESPACE = re.compile(r'[ \t\n\r]*', FLAGS) def decode(self, s, _w=WHITESPACE.match): """Return the Python representation of ``s`` (a ``str`` or ``unicode`` instance containing a JSON document) """ start_from = 0 while start_from < len(s): try: obj, end = self.raw_decode(s[start_from:], idx=_w(s[start_from:], 0).end()) except ValueError: raise _IncompleteJsonError(start_from) end = _w(s[start_from:], end).end() start_from += end yield obj class StreamingDockerClient(Client): def _stream_helper(self, response): """Generator for data coming from a chunked-encoded HTTP response.""" content_buf = '' for content in response.iter_content(chunk_size=256): content_buf += content try: for val in json.loads(content_buf, cls=_StreamingJSONDecoder): yield val content_buf = '' except _IncompleteJsonError as exc: content_buf = content_buf[exc.start_from:] class DockerfileBuildContext(object): def __init__(self, build_context_dir, dockerfile_subdir, repo, tag_names, push_token, build_uuid, cache_size_gb, pull_credentials=None): self._build_dir = build_context_dir self._dockerfile_subdir = dockerfile_subdir self._repo = repo self._tag_names = tag_names self._push_token = push_token self._status = StatusWrapper(build_uuid) self._build_logger = partial(build_logs.append_log_message, build_uuid) self._pull_credentials = pull_credentials self._cache_size_gb = cache_size_gb # Note: We have two different clients here because we (potentially) login # with both, but with different credentials that we do not want shared between # the build and push operations. self._push_cl = StreamingDockerClient(timeout=1200) self._build_cl = StreamingDockerClient(timeout=1200) dockerfile_path = os.path.join(self._build_dir, dockerfile_subdir, 'Dockerfile') if not os.path.exists(dockerfile_path): raise RuntimeError('Build job did not contain a Dockerfile.') # Compute the number of steps with open(dockerfile_path, 'r') as dockerfileobj: self._parsed_dockerfile = parse_dockerfile(dockerfileobj.read()) self.__inject_quay_repo_env(self._parsed_dockerfile, repo) self._num_steps = len(self._parsed_dockerfile.commands) with open(dockerfile_path, 'w') as dockerfileobj: dockerfileobj.write(serialize_dockerfile(self._parsed_dockerfile)) logger.debug('Will build and push to repo %s with tags named: %s', self._repo, self._tag_names) def __enter__(self): self.__cleanup_containers() self.__cleanup_images() self.__prune_cache() return self def __exit__(self, exc_type, value, traceback): self.__cleanup_containers() shutil.rmtree(self._build_dir) @staticmethod def __inject_quay_repo_env(parsed_dockerfile, quay_reponame): env_command = { 'command': 'ENV', 'parameters': 'QUAY_REPOSITORY %s' % quay_reponame } for index, command in reversed(list(enumerate(parsed_dockerfile.commands))): if command['command'] == 'FROM': new_command_index = index + 1 logger.debug('Injecting env command at dockerfile index: %s', new_command_index) parsed_dockerfile.commands.insert(new_command_index, env_command) break @staticmethod def __total_completion(statuses, total_images): percentage_with_sizes = float(len(statuses.values()))/total_images sent_bytes = sum([status['current'] for status in statuses.values()]) total_bytes = sum([status['total'] for status in statuses.values()]) return float(sent_bytes)/total_bytes*percentage_with_sizes @staticmethod def __monitor_completion(status_stream, required_message, status_updater, status_completion_key, num_images=0): images = {} for status in status_stream: logger.debug('%s: %s', status_completion_key, status) if 'status' in status: status_msg = status['status'] if status_msg == required_message: if 'progressDetail' in status and 'id' in status: image_id = status['id'] detail = status['progressDetail'] if 'current' in detail and 'total' in detail: images[image_id] = detail with status_updater as status_update: status_update[status_completion_key] = \ DockerfileBuildContext.__total_completion(images, max(len(images), num_images)) elif 'errorDetail' in status: message = 'Error pushing image.' if 'message' in status['errorDetail']: message = str(status['errorDetail']['message']) raise RuntimeError(message) def pull(self): # Login with the specified credentials (if any). if self._pull_credentials: logger.debug('Logging in with pull credentials: %s@%s', self._pull_credentials['username'], self._pull_credentials['registry']) self._build_cl.login(self._pull_credentials['username'], self._pull_credentials['password'], registry=self._pull_credentials['registry'], reauth=True) # Pull the image, in case it was updated since the last build image_and_tag = ':'.join(self._parsed_dockerfile.get_image_and_tag()) self._build_logger('Pulling base image: %s' % image_and_tag) pull_status = self._build_cl.pull(image_and_tag, stream=True) self.__monitor_completion(pull_status, 'Downloading', self._status, 'pull_completion') def build(self): # Start the build itself. logger.debug('Starting build.') with self._status as status: status['total_commands'] = self._num_steps logger.debug('Building to tags named: %s', self._tag_names) context_path = os.path.join(self._build_dir, self._dockerfile_subdir) logger.debug('Final context path: %s exists: %s', context_path, os.path.exists(context_path)) build_status = self._build_cl.build(path=context_path, stream=True) current_step = 0 built_image = None for status in build_status: fully_unwrapped = "" if isinstance(status, dict): keys_to_extract = ['error', 'status', 'stream'] for key in keys_to_extract: if key in status: fully_unwrapped = status[key] break if not fully_unwrapped: logger.debug('Status dict did not have any extractable keys and was: %s', status) elif isinstance(status, basestring): fully_unwrapped = status status_str = str(fully_unwrapped.encode('utf-8')) logger.debug('Status: %s', status_str) step_increment = re.search(r'Step ([0-9]+) :', status_str) if step_increment: self._build_logger(status_str, 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_update: status_update['current_command'] = current_step continue else: self._build_logger(status_str) complete = re.match(r'Successfully built ([a-z0-9]+)$', status_str) if complete: built_image = complete.group(1) logger.debug('Final image ID is: %s', built_image) continue # Get the image count if not built_image: return return built_image def push(self, built_image): # Login to the registry host = re.match(r'([a-z0-9.:]+)/.+/.+$', self._repo) if not host: raise RuntimeError('Invalid repo name: %s' % self._repo) for protocol in ['https', 'http']: registry_endpoint = '%s://%s/v1/' % (protocol, host.group(1)) logger.debug('Attempting login to registry: %s', registry_endpoint) try: self._push_cl.login('$token', self._push_token, registry=registry_endpoint) break except APIError: pass # Probably the wrong protocol for tag in self._tag_names: logger.debug('Tagging image %s as %s:%s', built_image, self._repo, tag) self._push_cl.tag(built_image, self._repo, tag) history = json.loads(self._push_cl.history(built_image)) num_images = len(history) logger.debug('Pushing to repo %s', self._repo) resp = self._push_cl.push(self._repo, stream=True) self.__monitor_completion(resp, 'Pushing', self._status, 'push_completion', num_images) def __cleanup_containers(self): # First clean up any containers that might be holding the images for running in self._build_cl.containers(quiet=True): logger.debug('Killing container: %s', running['Id']) self._build_cl.kill(running['Id']) # Next, remove all of the containers (which should all now be killed) for container in self._build_cl.containers(all=True, quiet=True): logger.debug('Removing container: %s', container['Id']) self._build_cl.remove_container(container['Id']) def __cleanup_images(self): """ Remove tags on internal nodes, and remove images older than the expiratino time. """ ids_to_images, ids_to_children = self.__compute_image_graph() # Untag all internal nodes, which are usually the base images for internal_id in ids_to_children.keys(): internal = ids_to_images[internal_id] if internal['RepoTags'] != NO_TAGS: for tag_name in internal['RepoTags']: self._build_cl.remove_image(tag_name) # Make sure all of the leaves have gibberish tags, and remove those older than our expiration leaves = set(ids_to_images.keys()) - set(ids_to_children.keys()) now = datetime.now() for leaf_id in leaves: leaf = ids_to_images[leaf_id] created = datetime.fromtimestamp(leaf['Created']) expiration = created + timedelta(hours=CACHE_EXPIRATION_PERIOD_HOURS) if expiration > now: # Assign a new tag as a uuid to preserve this image new_tag = str(uuid4()) self._build_cl.tag(leaf['Id'], new_tag) # Remove all of the existing tags if leaf['RepoTags'] != NO_TAGS: for tag_name in leaf['RepoTags']: self._build_cl.remove_image(tag_name) def __prune_cache(self): """ Remove the oldest leaf image until the cache size is the desired size. """ logger.debug('Pruning cache to size(gb): %s', self._cache_size_gb) while self.__compute_cache_size_gb() > self._cache_size_gb: logger.debug('Locating the oldest image in the cache to prune.') # Find the oldest tagged image and remove it oldest_creation_time = datetime.max oldest_image = None for image in self._build_cl.images(): created = datetime.fromtimestamp(image['Created']) if created < oldest_creation_time: oldest_creation_time = created oldest_image = image logger.debug('Removing oldest image from cache: %s', oldest_image['Id']) # Remove all tags on the oldest image if oldest_image['RepoTags'] == NO_TAGS: # Remove the image id directly since there are no tags self._build_cl.remove_image(oldest_image['Id']) else: # Remove all tags for tag_name in oldest_image['RepoTags']: self._build_cl.remove_image(tag_name) def __compute_cache_size_gb(self): all_images = self._build_cl.images(all=True) size_in_bytes = sum([img['Size'] for img in all_images]) size_in_gb = float(size_in_bytes)/1024/1024/1024 logger.debug('Computed cache size(gb) of: %s', size_in_gb) return size_in_gb def __compute_image_graph(self): all_images = self._build_cl.images(all=True) ids_to_images = {} ids_to_children = defaultdict(list) for image in all_images: if image['ParentId'] != '': ids_to_children[image['ParentId']].append(image) ids_to_images[image['Id']] = image return (ids_to_images, ids_to_children) class DockerfileBuildWorker(Worker): def __init__(self, cache_size_gb, *vargs, **kwargs): super(DockerfileBuildWorker, self).__init__(*vargs, **kwargs) self._mime_processors = { 'application/zip': DockerfileBuildWorker.__prepare_zip, 'application/x-zip-compressed': DockerfileBuildWorker.__prepare_zip, 'text/plain': DockerfileBuildWorker.__prepare_dockerfile, 'application/octet-stream': DockerfileBuildWorker.__prepare_dockerfile, 'application/x-tar': DockerfileBuildWorker.__prepare_tarball, 'application/gzip': DockerfileBuildWorker.__prepare_tarball, 'application/x-gzip': DockerfileBuildWorker.__prepare_tarball, } self._timeout = Event() self._cache_size_gb = cache_size_gb @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 def watchdog(self): logger.debug('Running build watchdog code.') docker_cl = Client() # Iterate the running containers and kill ones that have been running more than 20 minutes for container in docker_cl.containers(): start_time = datetime.fromtimestamp(container['Created']) running_time = datetime.now() - start_time if running_time > timedelta(minutes=TIMEOUT_PERIOD_MINUTES): logger.warning('Container has been running too long: %s with command: %s', container['Id'], container['Command']) docker_cl.kill(container['Id']) self._timeout.set() def process_queue_item(self, job_details): self._timeout.clear() repository_build = model.get_repository_build(job_details['namespace'], job_details['repository'], job_details['build_uuid']) pull_credentials = job_details.get('pull_credentials', None) job_config = json.loads(repository_build.job_config) resource_url = user_files.get_file_url(repository_build.resource_key) tag_names = job_config['docker_tags'] build_subdir = job_config['build_subdir'] repo = job_config['repository'] access_token = repository_build.access_token.code log_appender = partial(build_logs.append_log_message, repository_build.uuid) log_appender('initializing', build_logs.PHASE) start_msg = ('Starting job with resource url: %s repo: %s' % (resource_url, repo)) logger.debug(start_msg) docker_resource = requests.get(resource_url, stream=True) c_type = docker_resource.headers['content-type'] if ';' in c_type: c_type = c_type.split(';')[0] filetype_msg = ('Request to build type: %s with repo: %s and tags: %s' % (c_type, repo, tag_names)) logger.info(filetype_msg) log_appender(filetype_msg) if c_type not in self._mime_processors: log_appender('error', build_logs.PHASE) repository_build.phase = 'error' repository_build.save() log_appender('Unknown mime-type: %s' % c_type, build_logs.ERROR) return True build_dir = self._mime_processors[c_type](docker_resource) try: with DockerfileBuildContext(build_dir, build_subdir, repo, tag_names, access_token, repository_build.uuid, self._cache_size_gb, pull_credentials) as build_ctxt: log_appender('pulling', build_logs.PHASE) repository_build.phase = 'pulling' repository_build.save() build_ctxt.pull() log_appender('building', build_logs.PHASE) repository_build.phase = 'building' repository_build.save() built_image = build_ctxt.build() if not built_image: log_appender('error', build_logs.PHASE) repository_build.phase = 'error' repository_build.save() if self._timeout.is_set(): log_appender('Build step was terminated after %s minutes.' % TIMEOUT_PERIOD_MINUTES, build_logs.ERROR) else: log_appender('Unable to build dockerfile.', build_logs.ERROR) return True 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() log_appender(str(exc), build_logs.ERROR) return True return True desc = 'Worker daemon to monitor dockerfile build' parser = argparse.ArgumentParser(description=desc) parser.add_argument('-D', action='store_true', default=False, help='Run the worker in daemon mode.') parser.add_argument('--log', default='dockerfilebuild.log', help='Specify the log file for the worker as a daemon.') parser.add_argument('--cachegb', default=20, type=float, help='Maximum cache size in gigabytes.') args = parser.parse_args() ONE_HOUR = 60*60 worker = DockerfileBuildWorker(args.cachegb, dockerfile_build_queue, reservation_seconds=ONE_HOUR) if args.D: handler = logging.FileHandler(args.log) handler.setFormatter(formatter) root_logger.addHandler(handler) with daemon.DaemonContext(files_preserve=[handler.stream]): worker.start() else: handler = logging.StreamHandler() handler.setFormatter(formatter) root_logger.addHandler(handler) worker.start()