Add general+trackable logging to every request and add fine grain logging to the index and registry for determining possible performance regressions

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')

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' %
+    profile.debug('Creaing repository with owner: %s', get_authenticated_user().username)
-                 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' %
+      profile.debug('Setting checksum for image id: %s to %s', image['id'], image['checksum'])
-                   (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\'' %
+      profile.debug('Creating webhook for repository \'%s\' for url \'%s\'',
-                   (repo_string, webhook_data['url']))
+                    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

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)