ref(exceptions/logging): unify logging and make sure exceptions go into logs

Add a custom exception handler to deal with uncaught exceptions so they get properly logged to the stdout logging, and also return a 500 with a JSON body like everything else does.
A lot of scheduling logging has moved up from debug to info (the new default value) and now DEBUG=True (in the django config file) will cause debug information to outputting

tbgrep was added, usage would be k logs -f <controller pod> | tbgrep

Author: helgi

rootfs/api/exceptions.py

@@ -1,3 +1,38 @@
-class HealthcheckException(Exception):
+import logging
+from rest_framework.compat import set_rollback
+from rest_framework.exceptions import APIException, status
+from rest_framework.response import Response
+from rest_framework.views import exception_handler
+
+
+class HealthcheckException(APIException):
     """Exception class used for when the application's health check fails"""
     pass
+
+
+class DeisException(APIException):
+    status_code = 400
+
+
+class AlreadyExists(APIException):
+    status_code = 409
+
+
+class ServiceUnavailable(APIException):
+    status_code = 503
+    default_detail = 'Service temporarily unavailable, try again later.'
+
+
+def custom_exception_handler(exc, context):
+    # Call REST framework's default exception handler first,
+    # to get the standard error response.
+    response = exception_handler(exc, context)
+
+    # No response means DRF couldn't handle it
+    # Output a generic 500 in a JSON format
+    if response is None:
+        logging.exception('Uncaught Exception', exc_info=exc)
+        set_rollback()
+        return Response({'detail': 'Server Error'}, status=status.HTTP_500_INTERNAL_SERVER_ERROR)
+
+    return response

rootfs/api/models/__init__.py

@@ -14,34 +14,16 @@
 from django.db.models.signals import post_delete, post_save
 from django.dispatch import receiver
 
-from rest_framework.exceptions import ValidationError, APIException
+from rest_framework.exceptions import ValidationError
 from rest_framework.authtoken.models import Token
 
+from api.exceptions import DeisException, AlreadyExists, ServiceUnavailable  # noqa
 from api.utils import dict_merge
 from scheduler import KubeException
 
 logger = logging.getLogger(__name__)
 
 
-class DeisException(APIException):
-    status_code = 400
-
-
-class AlreadyExists(APIException):
-    status_code = 409
-
-
-class ServiceUnavailable(APIException):
-    status_code = 503
-    default_detail = 'Service temporarily unavailable, try again later.'
-
-
-def log_event(app, msg, level=logging.INFO):
-    # controller needs to know which app this log comes from
-    logger.log(level, "{}: {}".format(app.id, msg))
-    app.log(msg, level)
-
-
 def validate_label(value):
     """
     Check that the value follows the kubernetes name constraints
@@ -72,7 +54,7 @@ def _fetch_service_config(self, app):
             # Get the service from k8s to attach the domain correctly
             svc = self._scheduler._get_service(app, app).json()
         except KubeException as e:
-            raise ServiceUnavailable(str(e)) from e
+            raise ServiceUnavailable('Could not fetch Kubernetes Service {}'.format(app)) from e
 
         # Get minimum structure going if it is missing on the service
         if 'metadata' not in svc or 'annotations' not in svc['metadata']:
@@ -109,7 +91,7 @@ def _save_service_config(self, app, component, data):
         try:
             self._scheduler._update_service(app, app, svc)
         except KubeException as e:
-            raise ServiceUnavailable(str(e)) from e
+            raise ServiceUnavailable('Could not update Kubernetes Service {}'.format(app)) from e
 
 
 class UuidAuditedModel(AuditedModel):
@@ -144,35 +126,31 @@ def _log_build_created(**kwargs):
     if kwargs.get('created'):
         build = kwargs['instance']
         # log only to the controller; this event will be logged in the release summary
-        logger.info("{}: build {} created".format(build.app, build))
+        build.app.log("build {} created".format(build))
 
 
 def _log_release_created(**kwargs):
     if kwargs.get('created'):
         release = kwargs['instance']
-        # log only to the controller; this event will be logged in the release summary
-        logger.info("{}: release {} created".format(release.app, release))
         # append release lifecycle logs to the app
         release.app.log(release.summary)
 
 
 def _log_config_updated(**kwargs):
     config = kwargs['instance']
     # log only to the controller; this event will be logged in the release summary
-    logger.info("{}: config {} updated".format(config.app, config))
+    config.app.log("config {} updated".format(config))
 
 
 def _log_domain_added(**kwargs):
     if kwargs.get('created'):
         domain = kwargs['instance']
-        msg = "domain {} added".format(domain)
-        log_event(domain.app, msg)
+        domain.app.log("domain {} added".format(domain))
 
 
 def _log_domain_removed(**kwargs):
     domain = kwargs['instance']
-    msg = "domain {} removed".format(domain)
-    log_event(domain.app, msg)
+    domain.app.log("domain {} removed".format(domain))
 
 
 def _log_cert_added(**kwargs):

rootfs/api/models/app.py

@@ -15,8 +15,7 @@
 from jsonfield import JSONField
 
 from deis import __version__ as deis_version
-from api.models import UuidAuditedModel, log_event, AlreadyExists, \
-    DeisException, ServiceUnavailable
+from api.models import UuidAuditedModel, AlreadyExists, DeisException, ServiceUnavailable
 
 from api.utils import generate_app_name
 from api.models.release import Release
@@ -86,7 +85,7 @@ def save(self, *args, **kwargs):
                 if self._scheduler._get_namespace(self.id).status_code == 200:
                     # Namespace already exists
                     err = "{} already exists as a namespace in this kuberenetes setup".format(self.id)  # noqa
-                    log_event(self, err, logging.INFO)
+                    self.log(err, logging.INFO)
                     raise AlreadyExists(err)
             except KubeHTTPException:
                 pass
@@ -174,7 +173,7 @@ def create(self, *args, **kwargs):
         try:
             self._scheduler.create(self.id)
         except KubeException as e:
-            raise ServiceUnavailable(str(e)) from e
+            raise ServiceUnavailable('Kubernetes resources could not be created') from e
 
         # Attach the platform specific application sub domain to the k8s service
         # Only attach it on first release in case a customer has remove the app domain
@@ -183,11 +182,12 @@ def create(self, *args, **kwargs):
 
     def delete(self, *args, **kwargs):
         """Delete this application including all containers"""
+        self.log("deleting environment")
         try:
             # attempt to remove application from kubernetes
             self._scheduler.destroy(self.id)
         except KubeException as e:
-            raise ServiceUnavailable(str(e)) from e
+            raise ServiceUnavailable('Could not delete Kubernetes Namespace {}'.format(self.id)) from e  # noqa
 
         self._clean_app_logs()
         return super(App, self).delete(*args, **kwargs)
@@ -226,7 +226,7 @@ def restart(self, **kwargs):  # noqa
                 self._scheduler._delete_pod(self.id, pod['name'])
         except Exception as e:
             err = "warning, some pods failed to stop:\n{}".format(str(e))
-            log_event(self, err, logging.WARNING)
+            self.log(err, logging.WARNING)
 
         # Wait for pods to start
         try:
@@ -258,7 +258,7 @@ def restart(self, **kwargs):  # noqa
                 time.sleep(5)
         except Exception as e:
             err = "warning, some pods failed to start:\n{}".format(str(e))
-            log_event(self, err, logging.WARNING)
+            self.log(err, logging.WARNING)
 
         # Return the new pods
         pods = self.list_pods(**kwargs)
@@ -274,7 +274,7 @@ def _clean_app_logs(self):
             # Ignore errors deleting application logs.  An error here should not interfere with
             # the overall success of deleting an application, but we should log it.
             err = 'Error deleting existing application logs: {}'.format(e)
-            log_event(self, err, logging.WARNING)
+            self.log(err, logging.WARNING)
 
     def scale(self, user, structure):  # noqa
         """Scale containers up or down to match requested structure."""
@@ -317,7 +317,7 @@ def scale(self, user, structure):  # noqa
 
             msg = '{} scaled pods '.format(user.username) + ' '.join(
                 "{}={}".format(k, v) for k, v in list(structure.items()))
-            log_event(self, msg)
+            self.log(msg)
 
             return True
 
@@ -358,7 +358,7 @@ def _scale_pods(self, scale_types):
                 )
             except Exception as e:
                 err = '{} (scale): {}'.format(self._get_job_id(scale_type), e)
-                log_event(self, err, logging.ERROR)
+                self.log(err, logging.ERROR)
                 raise ServiceUnavailable(e) from e
 
     def deploy(self, release):
@@ -423,7 +423,7 @@ def deploy(self, release):
 
             except Exception as e:
                 err = '{} (app::deploy): {}'.format(self._get_job_id(scale_type), e)
-                log_event(self, err, logging.ERROR)
+                self.log(err, logging.ERROR)
                 raise ServiceUnavailable(err) from e
 
         # cleanup old releases from kubernetes
@@ -577,7 +577,7 @@ def pod_name(size=5, chars=string.ascii_lowercase + string.digits):
         entrypoint, command = self._get_command_run(command)
 
         name = self._get_job_id('run') + '-' + pod_name()
-        log_event(self, "{} on {} runs '{}'".format(user.username, name, command))
+        self.log("{} on {} runs '{}'".format(user.username, name, command))
 
         kwargs = {
             'memory': release.config.memory,
@@ -602,8 +602,7 @@ def pod_name(size=5, chars=string.ascii_lowercase + string.digits):
             return exit_code, output
         except Exception as e:
             err = '{} (run): {}'.format(name, e)
-            log_event(self, err, logging.ERROR)
-            raise ServiceUnavailable(str(e)) from e
+            raise ServiceUnavailable(err) from e
 
     def list_pods(self, *args, **kwargs):
         """Used to list basic information about pods running for a given application"""
@@ -653,7 +652,7 @@ def list_pods(self, *args, **kwargs):
             pass
         except Exception as e:
             err = '(list pods): {}'.format(e)
-            log_event(self, err, logging.ERROR)
+            self.log(err, logging.ERROR)
             raise ServiceUnavailable(err) from e
 
     def _scheduler_filter(self, **kwargs):

rootfs/api/models/certificate.py

@@ -188,7 +188,9 @@ def attach_in_kubernetes(self, domain):
                 try:
                     self._scheduler._update_secret(app, name, data)
                 except KubeException as e:
-                    raise ServiceUnavailable(str(e)) from e
+                    msg = 'There was a problem updating the certificate secret ' \
+                          '{} for {}'.format(name, app)
+                    raise ServiceUnavailable(msg) from e
 
         # get config for the service
         config = self._load_service_config(app, 'router')

rootfs/api/models/key.py

@@ -13,7 +13,7 @@ def validate_base64(value):
     try:
         base64.b64decode(value.split()[1])
     except Exception as e:
-        raise ValidationError(str(e))
+        raise ValidationError('Key contains invalid base64 chars') from e
 
 
 class Key(UuidAuditedModel):

rootfs/api/models/release.py

@@ -5,7 +5,7 @@
 
 from registry import publish_release, get_port as docker_get_port, RegistryException
 from api.utils import dict_diff
-from api.models import UuidAuditedModel, log_event, DeisException
+from api.models import UuidAuditedModel, DeisException
 from scheduler import KubeHTTPException
 
 logger = logging.getLogger(__name__)
@@ -87,10 +87,10 @@ def new(self, user, config, build, summary=None, source_version='latest'):
             release.publish()
         except DeisException as e:
             # If we cannot publish this app, just log and carry on
-            log_event(self.app, e)
+            self.app.log(e)
             pass
         except RegistryException as e:
-            log_event(self.app, e)
+            self.app.log(e)
             raise DeisException(str(e)) from e
 
         return release
@@ -113,15 +113,15 @@ def publish(self):
             # hostname tells Builder where to push images
             not registry.get('hostname', None)
         ):
-            log_event(self.app, '{} exists in the target registry. Using image for release {} of app {}'.format(self.build.image, self.version, self.app))  # noqa
+            self.app.log('{} exists in the target registry. Using image for release {} of app {}'.format(self.build.image, self.version, self.app))  # noqa
             return
 
         # return image if it is already in the registry, test host and then host + port
         if (
             self.build.image.startswith(settings.REGISTRY_HOST) or
             self.build.image.startswith(settings.REGISTRY_URL)
         ):
-            log_event(self.app, '{} exists in the target registry. Using image for release {} of app {}'.format(self.build.image, self.version, self.app))  # noqa
+            self.app.log('{} exists in the target registry. Using image for release {} of app {}'.format(self.build.image, self.version, self.app))  # noqa
             return
 
         # add tag if it was not provided
@@ -151,13 +151,13 @@ def get_port(self, routable=False):
 
             if self.build.type == "buildpack":
                 msg = "Using default port 5000 for build pack image {}".format(self.image)
-                log_event(self.app, msg)
+                self.app.log(msg)
                 return 5000
 
             # application has registry auth - $PORT is required
             if creds is not None:
                 if envs.get('PORT', None) is None:
-                    log_event(self.app, 'Private registry detected but no $PORT defined. Defaulting to $PORT 5000', logging.WARNING)  # noqa
+                    self.app.log('Private registry detected but no $PORT defined. Defaulting to $PORT 5000', logging.WARNING)  # noqa
                     return 5000
 
                 # User provided PORT
@@ -171,7 +171,7 @@ def get_port(self, routable=False):
             port = docker_get_port(self.image, deis_registry, creds)
             if port is None:
                 msg = "Expose a port or make the app non routable by changing the process type"
-                log_event(self.app, msg, logging.ERROR)
+                self.app.log(msg, logging.ERROR)
                 raise DeisException(msg)
 
             return port
@@ -233,7 +233,7 @@ def rollback(self, user, version=None):
         except Exception as e:
             if 'new_release' in locals():
                 new_release.delete()
-            raise DeisException(str(e))
+            raise DeisException(str(e)) from e
 
     def delete(self, *args, **kwargs):
         """Delete release DB record and any RCs from the affect release"""
@@ -244,16 +244,15 @@ def delete(self, *args, **kwargs):
             if e.response.status_code is not 404:
                 # Another problem came up
                 message = 'Could not to cleanup RCs for release {}'.format(self.version)
-                log_event(self.app, message)
+                self.app.log(message, level=logging.WARNING)
                 logger.warning(message + ' - ' + str(e))
         finally:
             super(Release, self).delete(*args, **kwargs)
 
     def cleanup_old(self):
         """Cleanup all but the latest release from Kubernetes"""
         latest_version = 'v{}'.format(self.version)
-        log_event(
-            self.app,
+        self.app.log(
             'Cleaning up RCS for releases older than {} (latest)'.format(latest_version),
             level=logging.DEBUG
         )
@@ -275,8 +274,7 @@ def cleanup_old(self):
                 controller_removal.append(current_version)
 
         if controller_removal:
-            log_event(
-                self.app,
+            self.app.log(
                 'Found the following versions to cleanup: {}'.format(', '.join(controller_removal)),  # noqa
                 level=logging.DEBUG
             )
@@ -285,7 +283,7 @@ def cleanup_old(self):
             self._delete_release_in_scheduler(self.app.id, version)
 
         # find stray env secrets to remove that may have been missed
-        log_event(self.app, 'Cleaning up orphaned environment var secrets', level=logging.DEBUG)
+        self.app.log('Cleaning up orphaned environment var secrets', level=logging.DEBUG)
         labels = {
             'heritage': 'deis',
             'app': self.app.id,

rootfs/api/tests/test_key.py

@@ -105,7 +105,7 @@ def test_ecdsa_key(self):
 
     def test_bad_key(self):
         response = self._check_bad_key(BAD_KEY)
-        self.assertEqual(response.data, {'public': ['Incorrect padding']})
+        self.assertEqual(response.data, {'public': ['Key contains invalid base64 chars']})
 
     def _check_duplicate_key(self, pubkey, pubkey2):
         """