Merge pull request #2958 from coreos-inc/joseph.schorr/QS-106/log-trimming

A bit of cleanup of our logging

app.py

@@ -123,8 +123,8 @@ class RequestWithId(Request):
 
 @app.before_request
 def _request_start():
-  logger.debug('Starting request: %s', request.path)
-  logger.info("request-start", extra={"request_id": request.request_id})
+  logger.debug('Starting request: %s (%s)', request.request_id, request.path,
+               extra={"request_id": request.request_id})
 
 
 DEFAULT_FILTER = lambda x: '[FILTERED]'
@@ -161,8 +161,7 @@ def _request_end(resp):
   if request.user_agent is not None:
     extra["user-agent"] = request.user_agent.string
 
-  logger.info("request-end", extra=extra)
-  logger.debug('Ending request: %s', request.path)
+  logger.debug('Ending request: %s (%s)', request.request_id, request.path, extra=extra)
   return resp
 
 

auth/oauth.py

@@ -34,7 +34,7 @@ def validate_oauth_token(token):
                           error_message='OAuth access token could not be validated')
 
   if validated.expires_at <= datetime.utcnow():
-    logger.info('OAuth access with an expired token: %s', token)
+    logger.warning('OAuth access with an expired token: %s', token)
     return ValidateResult(AuthKind.oauth, error_message='OAuth access token has expired')
 
   # Don't allow disabled users to login.

buildman/builder.py

@@ -1,10 +1,12 @@
 import logging
 import os
-import features
 import time
 import socket
 
+import features
+
 from app import app, userfiles as user_files, build_logs, dockerfile_build_queue
+from util.log import logfile_path
 
 from buildman.manager.enterprise import EnterpriseManager
 from buildman.manager.ephemeral import EphemeralBuilderManager
@@ -77,13 +79,13 @@ def run_build_manager():
   server.run('0.0.0.0', websocket_port, controller_port, ssl=ssl_context)
 
 if __name__ == '__main__':
-  logging.basicConfig(level=logging.DEBUG, format=LOG_FORMAT)
+  logging.config.fileConfig(logfile_path(debug=True), disable_existing_loggers=False)
   logging.getLogger('peewee').setLevel(logging.WARN)
   logging.getLogger('boto').setLevel(logging.WARN)
 
   if app.config.get('EXCEPTION_LOG_TYPE', 'FakeSentry') == 'Sentry':
     buildman_name = '%s:buildman' % socket.gethostname()
     setup_logging(SentryHandler(app.config.get('SENTRY_DSN', ''), name=buildman_name,
-                  level=logging.ERROR))
+                                level=logging.ERROR))
 
   run_build_manager()

buildman/component/buildcomponent.py

@@ -285,7 +285,7 @@ class BuildComponent(BaseComponent):
           raise Return(False)
       except InvalidRepositoryBuildException:
         build_id = self._current_job.repo_build.uuid
-        logger.info('Build %s was not found; repo was probably deleted', build_id)
+        logger.warning('Build %s was not found; repo was probably deleted', build_id)
         raise Return(False)
 
       BuildComponent._process_pushpull_status(status_dict, phase, log_data, self._image_info)
@@ -350,7 +350,7 @@ class BuildComponent(BaseComponent):
       try:
         yield From(self._build_status.set_phase(BUILD_PHASE.COMPLETE))
       except InvalidRepositoryBuildException:
-        logger.info('Build %s was not found; repo was probably deleted', build_id)
+        logger.warning('Build %s was not found; repo was probably deleted', build_id)
         raise Return()
 
       yield From(self._build_finished(BuildJobResult.COMPLETE))

endpoints/appr/registry.py

@@ -154,8 +154,8 @@ def show_package_release_manifests(namespace, package_name, release):
 @require_app_repo_read
 @anon_protect
 def pull(namespace, package_name, release, media_type):
+  logger.debug('Pull of release %s of app repository %s/%s', release, namespace, package_name)
   reponame = repo_name(namespace, package_name)
-  logger.info("pull %s", reponame)
   data = cnr_registry.pull(reponame, release, media_type, Package, blob_class=Blob)
   model.log_action('pull_repo', namespace, repo_name=package_name,
                    metadata={'release': release, 'mediatype': media_type})

endpoints/v1/index.py

@@ -184,8 +184,8 @@ def create_repository(namespace_name, repo_name):
   else:
     create_perm = CreateRepositoryPermission(namespace_name)
     if not create_perm.can():
-      logger.info('Attempt to create a new repo %s/%s with insufficient perms', namespace_name,
-                  repo_name)
+      logger.warning('Attempt to create a new repo %s/%s with insufficient perms', namespace_name,
+                     repo_name)
       msg = 'You do not have permission to create repositories in namespace "%(namespace)s"'
       abort(403, message=msg, issue='no-create-permission', namespace=namespace_name)
 

endpoints/v2/manifest.py

@@ -154,7 +154,6 @@ def _write_manifest(namespace_name, repo_name, manifest):
     raise NameInvalid()
 
   if not manifest.layers:
-    logger.info("manifest provided with no layers")
     raise ManifestInvalid(detail={'message': 'manifest does not reference any layers'})
 
   # Ensure all the blobs in the manifest exist.