diff --git a/application.py b/application.py index a5bb45edf..d4ba21913 100644 --- a/application.py +++ b/application.py @@ -1,7 +1,9 @@ import logging import logging.config +import uuid from app import app as application +from flask import request, Request from data.model import db as model_db @@ -19,6 +21,7 @@ from endpoints.callbacks import callback logger = logging.getLogger(__name__) +profile = logging.getLogger('application.profiler') application.register_blueprint(web) application.register_blueprint(callback, url_prefix='/oauth2') @@ -29,6 +32,27 @@ application.register_blueprint(api_bp, url_prefix='/api') application.register_blueprint(webhooks, url_prefix='/webhooks') application.register_blueprint(realtime, url_prefix='/realtime') +class RequestWithId(Request): + def __init__(self, *args, **kwargs): + super(RequestWithId, self).__init__(*args, **kwargs) + self.request_id = uuid.uuid4() + +@application.before_request +def _request_start(): + profile.debug('Starting request: %s', request.path) + + +@application.after_request +def _request_end(r): + profile.debug('Ending request: %s', request.path) + return r + +class InjectingFilter(logging.Filter): + def filter(self, record): + record.msg = '[request_id = %s] %s' % (request.request_id, record.msg) + return True + +profile.addFilter(InjectingFilter()) def close_db(exc): db = model_db @@ -37,11 +61,8 @@ def close_db(exc): db.close() application.teardown_request(close_db) +application.request_class = RequestWithId if __name__ == '__main__': - logging.config.fileConfig('conf/logging_local.conf', disable_existing_loggers=False) - - profile = logging.getLogger('application.profiler') - profile.debug('This is a profiling statement') - - application.run(port=5000, debug=True, threaded=True, host='0.0.0.0') \ No newline at end of file + logging.config.fileConfig('conf/logging_local.conf', disable_existing_loggers=False) + application.run(port=5000, debug=True, threaded=True, host='0.0.0.0') diff --git a/endpoints/index.py b/endpoints/index.py index 8271dda73..4aa3f8ec7 100644 --- a/endpoints/index.py +++ b/endpoints/index.py @@ -21,6 +21,7 @@ from util.http import abort logger = logging.getLogger(__name__) +profile = logging.getLogger('application.profiler') index = Blueprint('index', __name__) @@ -112,9 +113,15 @@ def create_user(): else: # New user case + profile.debug('Creating user') new_user = model.create_user(username, password, user_data['email']) + + profile.debug('Creating email code for user') code = model.create_confirm_email_code(new_user) + + profile.debug('Sending email code to user') send_confirmation_email(new_user.username, new_user.email, code.code) + return make_response('Created', 201) @@ -149,12 +156,12 @@ def update_user(username): update_request = request.get_json() if 'password' in update_request: - logger.debug('Updating user password.') + profile.debug('Updating user password') model.change_password(get_authenticated_user(), update_request['password']) if 'email' in update_request: - logger.debug('Updating user email') + profile.debug('Updating user email') model.update_email(get_authenticated_user(), update_request['email']) return jsonify({ @@ -170,9 +177,13 @@ def update_user(username): @parse_repository_name @generate_headers(role='write') def create_repository(namespace, repository): + profile.debug('Parsing image descriptions') image_descriptions = json.loads(request.data) + + profile.debug('Looking up repository') repo = model.get_repository(namespace, repository) + profile.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, @@ -196,11 +207,11 @@ def create_repository(namespace, repository): issue='no-create-permission', namespace=namespace) - logger.debug('Creaing repository with owner: %s' % - get_authenticated_user().username) + profile.debug('Creaing repository with owner: %s', get_authenticated_user().username) repo = model.create_repository(namespace, repository, get_authenticated_user()) + profile.debug('Determining added images') added_images = OrderedDict([(desc['id'], desc) for desc in image_descriptions]) new_repo_images = dict(added_images) @@ -209,12 +220,15 @@ def create_repository(namespace, repository): if existing.docker_image_id in new_repo_images: added_images.pop(existing.docker_image_id) + profile.debug('Creating/Linking necessary images') username = get_authenticated_user() and get_authenticated_user().username translations = {} for image_description in added_images.values(): model.find_create_or_link_image(image_description['id'], repo, username, translations) + + profile.debug('Created images') response = make_response('Created', 201) extra_params = { @@ -268,21 +282,23 @@ def update_images(namespace, repository): permission = ModifyRepositoryPermission(namespace, repository) if permission.can(): + profile.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') + profile.debug('Parsing image data') image_with_checksums = json.loads(request.data) updated_tags = {} for image in image_with_checksums: - logger.debug('Setting checksum for image id: %s to %s' % - (image['id'], image['checksum'])) + profile.debug('Setting checksum for image id: %s to %s', image['id'], image['checksum']) updated_tags[image['Tag']] = image['id'] model.set_image_checksum(image['id'], repo, image['checksum']) if get_authenticated_user(): + profile.debug('Publishing push event') username = get_authenticated_user().username # Mark that the user has pushed the repo. @@ -295,15 +311,18 @@ def update_images(namespace, repository): event = app.config['USER_EVENTS'].get_event(username) event.publish_event_data('docker-cli', user_data) + profile.debug('GCing repository') num_removed = model.garbage_collect_repository(namespace, repository) # Generate a job for each webhook that has been added to this repo + profile.debug('Adding webhooks for repository') + webhooks = model.list_webhooks(namespace, repository) for webhook in webhooks: webhook_data = json.loads(webhook.parameters) repo_string = '%s/%s' % (namespace, repository) - logger.debug('Creating webhook for repository \'%s\' for url \'%s\'' % - (repo_string, webhook_data['url'])) + profile.debug('Creating webhook for repository \'%s\' for url \'%s\'', + repo_string, webhook_data['url']) webhook_data['payload'] = { 'repository': repo_string, 'namespace': namespace, @@ -330,14 +349,17 @@ def get_repository_images(namespace, repository): permission = ReadRepositoryPermission(namespace, repository) # TODO invalidate token? + profile.debug('Looking up public status of repository') is_public = model.repository_is_public(namespace, repository) if permission.can() or is_public: # We can't rely on permissions to tell us if a repo exists anymore + profile.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') for image in model.get_repository_images(namespace, repository): new_image_view = { 'id': image.docker_image_id, @@ -345,6 +367,7 @@ def get_repository_images(namespace, repository): } all_images.append(new_image_view) + profile.debug('Building repository image response') resp = make_response(json.dumps(all_images), 200) resp.mimetype = 'application/json' @@ -353,6 +376,7 @@ def get_repository_images(namespace, repository): 'namespace': namespace, } + profile.debug('Logging the pull to Mixpanel and the log system') if get_validated_oauth_token(): oauth_token = get_validated_oauth_token() metadata['oauth_token_id'] = oauth_token.id diff --git a/endpoints/registry.py b/endpoints/registry.py index 9d981ba08..602c45036 100644 --- a/endpoints/registry.py +++ b/endpoints/registry.py @@ -21,7 +21,7 @@ from data import model registry = Blueprint('registry', __name__) logger = logging.getLogger(__name__) - +profile = logging.getLogger('application.profiler') class SocketReader(object): def __init__(self, fp): @@ -88,17 +88,28 @@ def set_cache_headers(f): @set_cache_headers def get_image_layer(namespace, repository, image_id, headers): permission = ReadRepositoryPermission(namespace, repository) + + profile.debug('Checking repo permissions') if permission.can() or model.repository_is_public(namespace, repository): + profile.debug('Looking up repo image') repo_image = model.get_repo_image(namespace, repository, image_id) + uuid = repo_image and repo_image.storage and repo_image.storage.uuid + profile.debug('Looking up the layer path') path = store.image_layer_path(namespace, repository, image_id, uuid) + + profile.debug('Looking up the direct download URL') direct_download_url = store.get_direct_download_url(path) + if direct_download_url: + profile.debug('Returning direct download URL') return redirect(direct_download_url) try: + profile.debug('Streaming layer data') return Response(store.stream_read(path), headers=headers) except IOError: + profile.debug('Image not found') abort(404, 'Image %(image_id)s not found', issue='unknown-image', image_id=image_id) @@ -109,25 +120,32 @@ 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') permission = ModifyRepositoryPermission(namespace, repository) if not permission.can(): abort(403) + profile.debug('Retrieving image') repo_image = model.get_repo_image(namespace, repository, image_id) + uuid = repo_image and repo_image.storage and repo_image.storage.uuid try: + profile.debug('Retrieving image data') json_data = store.get_content(store.image_json_path(namespace, repository, image_id, uuid)) except IOError: abort(404, 'Image %(image_id)s not found', issue='unknown-image', image_id=image_id) + profile.debug('Retrieving image path info') layer_path = store.image_layer_path(namespace, repository, image_id, uuid) mark_path = store.image_mark_path(namespace, repository, image_id, uuid) if store.exists(layer_path) and not store.exists(mark_path): abort(409, 'Image already exists', issue='image-exists', image_id=image_id) + profile.debug('Storing layer data') + input_stream = request.stream if request.headers.get('transfer-encoding') == 'chunked': # Careful, might work only with WSGI servers supporting chunked @@ -178,7 +196,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. - logger.debug('Queing diffs job for image: %s' % image_id) + profile.debug('Adding layer to diff queue') image_diff_queue.put([namespace, repository, image_id], json.dumps({ 'namespace': namespace, 'repository': repository, @@ -192,6 +210,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') permission = ModifyRepositoryPermission(namespace, repository) if not permission.can(): abort(403) @@ -204,17 +223,23 @@ def put_image_checksum(namespace, repository, image_id): abort(400, 'Checksum not found in Cookie for image %(imaage_id)s', issue='missing-checksum-cookie', image_id=image_id) + profile.debug('Looking up repo image') repo_image = model.get_repo_image(namespace, repository, image_id) + uuid = repo_image and repo_image.storage and repo_image.storage.uuid + + profile.debug('Looking up repo layer data') if not store.exists(store.image_json_path(namespace, repository, image_id, uuid)): abort(404, 'Image not found: %(image_id)s', issue='unknown-image', image_id=image_id) + profile.debug('Marking image path') mark_path = store.image_mark_path(namespace, repository, image_id, uuid) if not store.exists(mark_path): abort(409, 'Cannot set checksum for image %(image_id)s', issue='image-write-error', image_id=image_id) + profile.debug('Storing image checksum') err = store_checksum(namespace, repository, image_id, uuid, checksum) if err: abort(400, err) @@ -231,7 +256,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. - logger.debug('Queing diffs job for image: %s' % image_id) + profile.debug('Adding layer to diff queue') image_diff_queue.put([namespace, repository, image_id], json.dumps({ 'namespace': namespace, 'repository': repository, @@ -247,20 +272,24 @@ 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') permission = ReadRepositoryPermission(namespace, repository) if not permission.can() and not model.repository_is_public(namespace, repository): abort(403) + profile.debug('Looking up repo image') repo_image = model.get_repo_image(namespace, repository, image_id) uuid = repo_image and repo_image.storage and repo_image.storage.uuid + profile.debug('Looking up repo layer data') try: data = store.get_content(store.image_json_path(namespace, repository, image_id, uuid)) except IOError: flask_abort(404) + profile.debug('Looking up repo layer size') try: size = store.get_size(store.image_layer_path(namespace, repository, image_id, uuid)) @@ -268,6 +297,7 @@ def get_image_json(namespace, repository, image_id, headers): except OSError: pass + profile.debug('Retrieving checksum') checksum_path = store.image_checksum_path(namespace, repository, image_id, uuid) if store.exists(checksum_path): @@ -284,14 +314,17 @@ 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') permission = ReadRepositoryPermission(namespace, repository) if not permission.can() and not model.repository_is_public(namespace, repository): abort(403) + profile.debug('Looking up repo image') repo_image = model.get_repo_image(namespace, repository, image_id) uuid = repo_image and repo_image.storage and repo_image.storage.uuid + profile.debug('Looking up image data') try: data = store.get_content(store.image_ancestry_path(namespace, repository, image_id, uuid)) @@ -299,8 +332,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') response = make_response(json.dumps(json.loads(data)), 200) response.headers.extend(headers) + + profile.debug('Done') return response @@ -335,10 +371,12 @@ def store_checksum(namespace, repository, image_id, uuid, checksum): @process_auth @extract_namespace_repo_from_session def put_image_json(namespace, repository, image_id): + profile.debug('Checking repo permissions') permission = ModifyRepositoryPermission(namespace, repository) if not permission.can(): abort(403) + profile.debug('Parsing image JSON') try: data = json.loads(request.data) except json.JSONDecodeError: @@ -351,6 +389,7 @@ 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') repo_image = model.get_repo_image(namespace, repository, image_id) uuid = repo_image and repo_image.storage and repo_image.storage.uuid @@ -358,12 +397,14 @@ def put_image_json(namespace, repository, image_id): checksum = request.headers.get('X-Docker-Checksum') if checksum: # Storing the checksum is optional at this stage + profile.debug('Storing image checksum') err = store_checksum(namespace, repository, image_id, uuid, checksum) if err: abort(400, err, issue='write-error') else: # We cleanup any old checksum in case it's a retry after a fail + profile.debug('Cleanup old checksum') store.remove(store.image_checksum_path(namespace, repository, image_id, uuid)) if image_id != data['id']: @@ -374,18 +415,26 @@ def put_image_json(namespace, repository, image_id): parent_image = None if parent_id: + profile.debug('Looking up parent image') parent_image = model.get_repo_image(namespace, repository, parent_id) + parent_uuid = (parent_image and parent_image.storage and parent_image.storage.uuid) + if parent_id: + profile.debug('Looking up parent image data') + if (parent_id and not store.exists(store.image_json_path(namespace, repository, parent_id, 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') json_path = store.image_json_path(namespace, repository, image_id, uuid) mark_path = store.image_mark_path(namespace, repository, image_id, uuid) + + profile.debug('Checking if image already exists') if store.exists(json_path) and not store.exists(mark_path): abort(409, 'Image already exists', issue='image-exists', image_id=image_id) @@ -394,13 +443,23 @@ def put_image_json(namespace, repository, image_id): # save the metadata command_list = data.get('container_config', {}).get('Cmd', None) command = json.dumps(command_list) if command_list else None + + profile.debug('Setting image metadata') model.set_image_metadata(image_id, namespace, repository, data.get('created'), data.get('comment'), command, parent_image) + + profile.debug('Putting mark path') store.put_content(mark_path, 'true') + + profile.debug('Putting json path') store.put_content(json_path, request.data) + + profile.debug('Generating image ancestry') generate_ancestry(namespace, repository, image_id, uuid, parent_id, parent_uuid) + + profile.debug('Done') return make_response('true', 200)