Use mozlog for application logging

landoapi/api/landings.py

@@ -5,6 +5,7 @@
 Transplant API
 See the OpenAPI Specification for this API in the spec/swagger.yml file.
 """
+import logging
 from connexion import problem
 from flask import request
 from sqlalchemy.orm.exc import NoResultFound
@@ -13,23 +14,46 @@
     TRANSPLANT_JOB_FAILED, TRANSPLANT_JOB_LANDED
 )
 
+logger = logging.getLogger(__name__)
+
 
 def land(data, api_key=None):
     """ API endpoint at /revisions/{id}/transplants to land revision. """
     # get revision_id from body
     revision_id = data['revision_id']
+    logger.info(
+        {
+            'path': request.path,
+            'method': request.method,
+            'data': data,
+            'msg': 'landing requested by user'
+        }, 'landing.invoke'
+    )
     try:
         landing = Landing.create(revision_id, api_key)
     except RevisionNotFoundException:
         # We could not find a matching revision.
+        logger.info(
+            {
+                'revision': revision_id,
+                'msg': 'revision not found'
+            }, 'landing.failure'
+        )
         return problem(
             404,
             'Revision not found',
             'The requested revision does not exist',
             type='https://developer.mozilla.org/en-US/docs/Web/HTTP/Status/404'
         )
-    except LandingNotCreatedException:
+    except LandingNotCreatedException as exc:
         # We could not find a matching revision.
+        logger.info(
+            {
+                'revision': revision_id,
+                'exc': exc,
+                'msg': 'error creating landing',
+            }, 'landing.error'
+        )
         return problem(
             502,
             'Landing not created',

landoapi/app.py

@@ -5,23 +5,33 @@
 
 import click
 import connexion
+import logging
 
 from connexion.resolver import RestyResolver
 from landoapi.dockerflow import dockerflow
 from landoapi.models.storage import alembic, db
+from mozlogging import MozLogFormatter
+
+logger = logging.getLogger(__name__)
 
 
 def create_app(version_path):
     """Construct an application instance."""
+    initialize_logging()
+
     app = connexion.App(__name__, specification_dir='spec/')
     app.add_api('swagger.yml', resolver=RestyResolver('landoapi.api'))
 
     # Get the Flask app being wrapped by the Connexion app.
     flask_app = app.app
     flask_app.config['VERSION_PATH'] = version_path
-    flask_app.config.setdefault(
+    log_config_change('VERSION_PATH', version_path)
+
+    db_uri = flask_app.config.setdefault(
         'SQLALCHEMY_DATABASE_URI', os.environ.get('DATABASE_URL', 'sqlite://')
     )
+    log_config_change('SQLALCHEMY_DATABASE_URI', db_uri)
+
     flask_app.config['SQLALCHEMY_TRACK_MODIFICATIONS'] = False
     flask_app.config['ALEMBIC'] = {'script_location': '/migrations/'}
 
@@ -36,6 +46,32 @@ def create_app(version_path):
     return app
 
 
+def initialize_logging():
+    """Initialize application-wide logging."""
+    mozlog_handler = logging.StreamHandler()
+    mozlog_handler.setFormatter(MozLogFormatter())
+
+    # We need to configure the logger just for our application code.  This is
+    # because the MozLogFormatter changes the signature of the standard
+    # library logging functions.  Any code that tries to log a message assuming
+    # the standard library's formatter is in place, such as the code in the
+    # libraries we use, with throw an error if the MozLogFormatter tries to
+    # handle the message.
+    app_logger = logging.getLogger('landoapi')
+
+    # Stop our specially-formatted log messages from bubbling up to any
+    # Flask-installed loggers that may be present.  They will throw an exception
+    # if they handle our messages.
+    app_logger.propagate = False
+
+    app_logger.addHandler(mozlog_handler)
+
+    level = os.environ.get('LOG_LEVEL', 'INFO')
+    app_logger.setLevel(level)
+
+    log_config_change('LOG_LEVEL', level)
+
+
 @click.command()
 @click.option('--debug', envvar='DEBUG', is_flag=True)
 @click.option('--port', envvar='PORT', default=8888)
@@ -51,3 +87,13 @@ def development_server(debug, port, version_path):
     """
     app = create_app(version_path)
     app.run(debug=debug, port=port, host='0.0.0.0')
+
+
+def log_config_change(setting_name, value):
+    """Helper to log configuration changes.
+
+    Args:
+        setting_name: The setting being changed.
+        value: The setting's new value.
+    """
+    logger.info({'setting': setting_name, 'value': value}, 'app.configure')

landoapi/dockerflow.py

@@ -31,12 +31,14 @@ def heartbeat():
     phab = PhabricatorClient(api_key='')
     try:
         phab.check_connection()
-    except PhabricatorAPIException as exc:
+    except PhabricatorAPIException:
         logger.warning(
-            'heartbeat: problem, Phabricator API connection', exc_info=exc
+            {
+                'msg': 'problem connecting to Phabricator',
+            }, 'heartbeat'
         )
         return 'heartbeat: problem', 502
-    logger.info('heartbeat: ok, all services are up')
+    logger.info({'msg': 'ok, all services are up'}, 'heartbeat')
     return 'heartbeat: ok', 200
 
 

landoapi/models/landing.py

@@ -3,11 +3,15 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 import os
 
+import logging
+
 from landoapi.hgexportbuilder import build_patch_for_revision
 from landoapi.models.storage import db
 from landoapi.phabricator_client import PhabricatorClient
 from landoapi.transplant_client import TransplantClient
 
+logger = logging.getLogger(__name__)
+
 TRANSPLANT_JOB_STARTING = 'pending'
 TRANSPLANT_JOB_STARTED = 'started'
 TRANSPLANT_JOB_LANDED = 'landed'
@@ -72,6 +76,14 @@ def create(cls, revision_id, phabricator_api_key=None):
         landing.status = TRANSPLANT_JOB_STARTED
         landing.save()
 
+        logger.info(
+            {
+                'revision': revision_id,
+                'landing': landing.id,
+                'msg': 'landing created for revision'
+            }, 'landing.success'
+        )
+
         return landing
 
     def save(self):

landoapi/transplant_client.py

@@ -3,12 +3,16 @@
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import os
+
+import logging
 import requests
 import requests_mock
 
 from sqlalchemy import text
 from landoapi.models.storage import db
 
+logger = logging.getLogger(__name__)
+
 
 class TransplantClient:
     """ A class to interface with Transplant's API. """
@@ -48,8 +52,26 @@ def land(self, ldap_username, hgpatch, tree, pingback, request):
             }
         )
 
-        # Transplant API is responding with a created request_id of the job
-        return result.get('request_id') if result else None
+        if result:
+            logger.info(
+                {
+                    'service': 'transplant',
+                    'username': ldap_username,
+                    'msg': 'patch sent to transplant service',
+                }, 'transplant.success'
+            )
+            return result.get('request_id')
+        else:
+            # Transplant API responded with no data, indicating an error of
+            # some sort.
+            logger.info(
+                {
+                    'service': 'transplant',
+                    'username': ldap_username,
+                    'msg': 'received an empty response from the transplant service',
+                }, 'transplant.failure'
+            )   # yapf: disable
+            return None
 
     def _request(self, url, data=None, params=None, method='GET'):
         data = data if data else {}
@@ -64,6 +86,16 @@ def _request(self, url, data=None, params=None, method='GET'):
         status_code = response.status_code
         response = response.json()
 
+        logger.info(
+            {
+                'code': status_code,
+                'method': method,
+                'service': 'transplant',
+                'url': self.api_url,
+                'path': url,
+            }, 'request.summary'
+        )
+
         if 'error' in response:
             exp = TransplantAPIException()
             exp.error_code = status_code

requirements/common.txt

@@ -70,3 +70,6 @@ python-dateutil==2.6.0 \
 Flask-Alembic==2.0.1 \
     --hash=sha256:05a1e6f4148dbfcc9280a393373bfbd250af6f9f4f0ca9f744ef8f7376a3deec \
     --hash=sha256:7e67740b0b08d58dcae0c701d56b56e60f5fa4af907bb82b4cb0469229ba94ff
+mozlogging==0.1.0 \
+    --hash=sha256:2fc3d520a17b048c8723abdba19f6c01f2bcaf4182944aaac5906f28bd5b7d77 \
+    --hash=sha256:2e1362b80418b845164d8d47337da838dade05720dbaf17956d1cafebc511b94