Adapt logging setup to work when the API server is run under gunicorn.

Summary:
Run with:
  gunicorn --worker-class inbox.api.wsgi.InboxWSGIWorker --logger-class inbox.api.wsgi.GunicornLogger inbox.api.srv:app ...

This also requires some minor changes to our existing logging setup, because
gunicorn passes positional arguments in its logging messages
(`self.log.info('message %s', some_value)`) but structlog can't currently
handle that (hynek/structlog#19).

Test Plan:
Run `bin/inbox-api` and `gunicorn --worker-class
inbox.api.wsgi.InboxWSGIWorker --logger-class inbox.api.wsgi.GunicornLogger
--workers=1 --bind 127.0.0.1:5555 inbox.api.srv:app` and make some API
requests.

Reviewers: spang

Reviewed By: spang

Differential Revision: https://review.inboxapp.com/D235

bin/inbox-api

@@ -17,6 +17,7 @@ from setproctitle import setproctitle; setproctitle('inbox-api')
 from gevent import monkey; monkey.patch_all()
 from gevent.pywsgi import WSGIServer
 
+from inbox.api.wsgi import InboxWSGIHandler
 from inbox.log import get_logger, configure_logging
 from inbox.util.startup import preflight, load_overrides
 
@@ -37,7 +38,6 @@ if args.config:
 
 configure_logging(args.prod)
 
-
 # We need to import this down here, because this in turn imports
 # ignition.engine, which has to happen *after* we read any config overrides for
 # the database parameters. Boo for imports with side-effects.
@@ -53,7 +53,8 @@ def start():
     from inbox.transactions.actions import SyncbackService
     SyncbackService().start()
 
-    http_server = WSGIServer(('', int(args.port)), app, log=inbox_logger)
+    http_server = WSGIServer(('', int(args.port)), app, log=inbox_logger,
+                             handler_class=InboxWSGIHandler)
     inbox_logger.info('Starting API server on port {0}'.format(args.port))
     http_server.serve_forever()
 

inbox/api/srv.py

@@ -1,4 +1,3 @@
-from gevent.pywsgi import WSGIHandler
 from flask import Flask, request
 
 from inbox.api.kellogs import APIEncoder
@@ -10,29 +9,7 @@
 app = Flask(__name__)
 # Handle both /endpoint and /endpoint/ without redirecting.
 # Note that we need to set this *before* registering the blueprint.
-
-
-# gevent.pywsgi tries to call log.write(), but Python logger objects implement
-# log.debug(), log.info(), etc., so we need to monkey-patch log_request(). See
-# http://stackoverflow.com/questions/9444405/gunicorn-and-websockets
-def log_request(self, *args):
-    log = self.server.log
-    length = self.response_length
-    if self.time_finish:
-        request_time = round(self.time_finish - self.time_start, 6)
-    if isinstance(self.client_address, tuple):
-        client_address = self.client_address[0]
-    else:
-        client_address = self.client_address
-    # STOPSHIP(emfree) seems this attribute may be missing?
-    status = getattr(self, 'status', None)
-    requestline = getattr(self, 'requestline', None)
-    log.info(length=length,
-             request_time=request_time,
-             client_address=client_address,
-             status=status,
-             requestline=requestline)
-WSGIHandler.log_request = log_request
+app.url_map.strict_slashes = False
 
 
 @app.before_request
@@ -73,5 +50,4 @@ def home():
 </body></html>
 """
 
-app.url_map.strict_slashes = False
 app.register_blueprint(ns_api)  # /n/<namespace_id>/...

inbox/api/wsgi.py

@@ -0,0 +1,51 @@
+from gevent.pywsgi import WSGIHandler, WSGIServer
+from gunicorn.workers.ggevent import GeventWorker
+import gunicorn.glogging
+import inbox.log
+
+
+class InboxWSGIHandler(WSGIHandler):
+    """Custom WSGI handler class to customize request logging. Based on
+    gunicorn.workers.ggevent.PyWSGIHandler."""
+    def log_request(self):
+        # gevent.pywsgi tries to call log.write(), but Python logger objects
+        # implement log.debug(), log.info(), etc., so we need to monkey-patch
+        # log_request(). See
+        # http://stackoverflow.com/questions/9444405/gunicorn-and-websockets
+        log = self.server.log
+        length = self.response_length
+        if self.time_finish:
+            request_time = round(self.time_finish - self.time_start, 6)
+        if isinstance(self.client_address, tuple):
+            client_address = self.client_address[0]
+        else:
+            client_address = self.client_address
+        status = getattr(self, 'status', None)
+        requestline = getattr(self, 'requestline', None)
+
+        log.info('request handled',
+                 length=length,
+                 request_time=request_time,
+                 client_address=client_address,
+                 status=status,
+                 requestline=requestline)
+
+    def get_environ(self):
+        env = super(InboxWSGIHandler, self).get_environ()
+        env['gunicorn.sock'] = self.socket
+        env['RAW_URI'] = self.path
+        return env
+
+
+class InboxWSGIWorker(GeventWorker):
+    """Custom worker class for gunicorn. Based on
+    gunicorn.workers.ggevent.GeventPyWSGIWorker."""
+    server_class = WSGIServer
+    wsgi_handler = InboxWSGIHandler
+
+
+class GunicornLogger(gunicorn.glogging.Logger):
+    def __init__(self, cfg):
+        gunicorn.glogging.Logger.__init__(self, cfg)
+        inbox.log.configure_logging(is_prod=True)
+        self.error_log = inbox.log.get_logger()

inbox/log.py

@@ -47,6 +47,48 @@ def _record_module(logger, name, event_dict):
     return event_dict
 
 
+def _format_string_renderer(_, __, event_dict):
+    """Use with the BoundLogger class below to properly handle messages of the
+    form `log.info('some message to format %s', some_value')`."""
+    positional_args = event_dict.get('_positional_args')
+    if positional_args:
+        event_dict['event'] = event_dict['event'] % positional_args
+        del event_dict['_positional_args']
+    return event_dict
+
+
+class BoundLogger(structlog._base.BoundLoggerBase):
+    """Adaptation of structlog.stdlib.BoundLogger to accept positional
+    arguments. See https://github.com/hynek/structlog/pull/23/
+    (we can remove this if that ever gets merged)."""
+    def debug(self, event=None, *args, **kw):
+        return self._proxy_to_logger('debug', event, *args, **kw)
+
+    def info(self, event=None, *args, **kw):
+        return self._proxy_to_logger('info', event, *args, **kw)
+
+    def warning(self, event=None, *args, **kw):
+        return self._proxy_to_logger('warning', event, *args, **kw)
+
+    warn = warning
+
+    def error(self, event=None, *args, **kw):
+        return self._proxy_to_logger('error', event, *args, **kw)
+
+    def critical(self, event=None, *args, **kw):
+        return self._proxy_to_logger('critical', event, *args, **kw)
+
+    # Note(emfree): We could also add an `exception` method here to support
+    # `log.exception(...)`.
+
+    def _proxy_to_logger(self, method_name, event=None, *event_args,
+                         **event_kw):
+        if event_args:
+            event_kw['_positional_args'] = event_args
+        return super(BoundLogger, self)._proxy_to_logger(method_name, event,
+                                                         **event_kw)
+
+
 structlog.configure(
     processors=[
         structlog.stdlib.filter_by_level,
@@ -55,11 +97,12 @@ def _record_module(logger, name, event_dict):
         structlog.processors.format_exc_info,
         _record_module,
         _record_level,
+        _format_string_renderer,
         structlog.processors.JSONRenderer(),
     ],
     context_class=dict,
     logger_factory=structlog.stdlib.LoggerFactory(),
-    wrapper_class=structlog.stdlib.BoundLogger,
+    wrapper_class=BoundLogger,
     cache_logger_on_first_use=True,
 )
 get_logger = structlog.get_logger