feat: update logging for newstyle twisted and file output

Updates all logging calls to use the newer logging utilities in
twisted. This obsoletes the use of eliot, as twisteds logger can
handle arbitrary keywords. The logging handling has been revamped
into a more easily testable class that implements twisteds IObserver
for easy logger observing.

log_level support has been re-added so that calls can be appropriately
scoped by logging type. Existing info/msg log calls now use appropriate
log levels, with delayed function calls to prevent unnecessary overhead
when formatting objects if the log message is ignored.

Closes #419

.travis.yml

@@ -1,11 +1,10 @@
 language: python
 sudo: false
 python:
-  - "pypy"
+  - "2.7"
 install:
-  - wget https://bitbucket.org/pypy/pypy/downloads/pypy-5.0.0-linux64.tar.bz2
-  - tar xjvf pypy-5.0.0-linux64.tar.bz2
-  - virtualenv -p pypy-5.0.0-linux64/bin/pypy pypy
+  - virtualenv pypy
+  - cd pypy/bin && ln -s python pypy && cd ../..
   - source pypy/bin/activate
   - make travis
 script: tox -- --with-coverage --cover-xml --cover-package=autopush

autopush/db.py

@@ -2,7 +2,6 @@
 from __future__ import absolute_import
 
 import datetime
-import logging
 import random
 import time
 import uuid
@@ -21,9 +20,6 @@
 
 from autopush.utils import generate_hash
 
-
-log = logging.getLogger(__file__)
-
 key_hash = ""
 TRACK_DB_CALLS = False
 DB_CALLS = []
@@ -53,8 +49,6 @@ def hasher(uaid):
 
 
 def normalize_id(id):
-    if not id:
-        return id
     if (len(id) == 36 and
             id[8] == id[13] == id[18] == id[23] == '-'):
         return id.lower()
@@ -434,7 +428,6 @@ def update_message(self, uaid, channel_id, message_id, ttl, data=None,
             else:
                 expr += " REMOVE #dd, headers"
             expr_values = self.encode({":%s" % k: v for k, v in item.items()})
-            log.debug(expr_values)
             conn.update_item(
                 self.table.table_name,
                 db_key,

autopush/endpoint.py

@@ -38,7 +38,6 @@
 from cryptography.fernet import InvalidToken
 from twisted.internet.defer import Deferred
 from twisted.internet.threads import deferToThread
-from twisted.python import log
 
 from autopush.db import (
     generate_last_connect,
@@ -220,13 +219,13 @@ def _response_err(self, fail):
         running.
 
         """
-        log.err(fail, **self._client_info)
+        self.log.failure(fail, **self._client_info)
         self._write_response(500, 999)
 
     def _overload_err(self, fail):
         """errBack for throughput provisioned exceptions"""
         fail.trap(ProvisionedThroughputExceededException)
-        log.msg("Throughput Exceeded", **self._client_info)
+        self.log.info("Throughput Exceeded", **self._client_info)
         self._write_response(503, 201)
 
     def _router_response(self, response):
@@ -248,40 +247,40 @@ def _router_fail_err(self, fail):
         fail.trap(RouterException)
         exc = fail.value
         if exc.log_exception:
-            log.err(fail, **self._client_info)  # pragma nocover
+            self.log.failure(fail, **self._client_info)  # pragma nocover
         if 200 <= exc.status_code < 300:
-            log.msg("Success", status_code=exc.status_code,
-                    logged_status=exc.logged_status or "",
-                    **self._client_info)
+            self.log.info("Success", status_code=exc.status_code,
+                          logged_status=exc.logged_status or "",
+                          **self._client_info)
         elif 400 <= exc.status_code < 500:
-            log.msg("Client error", status_code=exc.status_code,
-                    logged_status=exc.logged_status or "",
-                    errno=exc.errno or "",
-                    **self._client_info)
+            self.log.info("Client error", status_code=exc.status_code,
+                          logged_status=exc.logged_status or "",
+                          errno=exc.errno or "",
+                          **self._client_info)
         self._router_response(exc)
 
     def _uaid_not_found_err(self, fail):
         """errBack for uaid lookup not finding the user"""
         fail.trap(ItemNotFound)
-        log.msg("UAID not found in AWS.", **self._client_info)
+        self.log.debug("UAID not found in AWS.", **self._client_info)
         self._write_response(410, 103)
 
     def _token_err(self, fail):
         """errBack for token decryption fail"""
         fail.trap(InvalidToken, InvalidTokenException)
-        log.msg("Invalid token", **self._client_info)
+        self.log.debug("Invalid token", **self._client_info)
         self._write_response(400, 102)
 
     def _auth_err(self, fail):
         """errBack for invalid auth token"""
         fail.trap(VapidAuthException)
-        log.msg("Invalid Auth token", **self._client_info)
+        self.log.debug("Invalid Auth token", **self._client_info)
         self._write_unauthorized_response(message=fail.value.message)
 
     def _chid_not_found_err(self, fail):
         """errBack for unknown chid"""
         fail.trap(ItemNotFound, ValueError)
-        log.msg("CHID not found in AWS.", **self._client_info)
+        self.log.debug("CHID not found in AWS.", **self._client_info)
         self._write_response(410, 106)
 
     #############################################################
@@ -307,7 +306,7 @@ def _invalid_auth(self, fail):
         message = fail.value.message or repr(fail.value)
         if isinstance(fail.value, AssertionError):
             message = "A decryption error occurred"
-        log.msg("Invalid bearer token: " + message, **self._client_info)
+        self.log.debug("Invalid bearer token: " + message, **self._client_info)
         raise VapidAuthException("Invalid bearer token: " + message)
 
     def _process_auth(self, result):
@@ -380,7 +379,7 @@ def _delete_message(self, kind, uaid, chid):
         return d
 
     def _delete_completed(self, response):
-        log.msg("Message Deleted", status_code=204, **self._client_info)
+        self.log.info("Message Deleted", status_code=204, **self._client_info)
         self.set_status(204)
         self.finish()
 
@@ -439,8 +438,8 @@ def _uaid_lookup_results(self, result):
         try:
             self.router = self.ap_settings.routers[router_key]
         except KeyError:
-            log.msg("Invalid router requested", status_code=400, errno=108,
-                    **self._client_info)
+            self.log.debug("Invalid router requested", status_code=400,
+                           errno=108, **self._client_info)
             return self._write_response(400, 108,
                                         message="Invalid router")
 
@@ -457,13 +456,13 @@ def _uaid_lookup_results(self, result):
             req_fields = ["content-encoding", "encryption"]
             if data and not all([x in self.request.headers
                                  for x in req_fields]):
-                log.msg("Client error", status_code=400, errno=101,
-                        **self._client_info)
+                self.log.debug("Client error", status_code=400, errno=101,
+                               **self._client_info)
                 return self._write_response(400, 101)
             if ("encryption-key" in self.request.headers and
                     "crypto-key" in self.request.headers):
-                log.msg("Client error", status_code=400, errno=110,
-                        **self._client_info)
+                self.log.debug("Client error", status_code=400, errno=110,
+                               **self._client_info)
                 return self._write_response(
                     400, 110, message="Invalid crypto headers")
             self._client_info["message_size"] = len(data) if data else 0
@@ -478,13 +477,13 @@ def _uaid_lookup_results(self, result):
             # Cap the TTL to our MAX_TTL
             ttl = min(ttl, MAX_TTL)
         else:
-            log.msg("Client error", status_code=400,
-                    errno=112, **self._client_info)
+            self.log.debug("Client error", status_code=400,
+                           errno=112, **self._client_info)
             return self._write_response(400, 112, message="Invalid TTL header")
 
         if data and len(data) > self.ap_settings.max_data:
-            log.msg("Client error", status_code=400, errno=104,
-                    **self._client_info)
+            self.log.debug("Client error", status_code=400, errno=104,
+                           **self._client_info)
             return self._write_response(
                 413, 104, message="Data payload too large")
 
@@ -538,9 +537,10 @@ def _router_completed(self, response, uaid_data):
             return d
         else:
             if response.status_code == 200 or response.logged_status == 200:
-                log.msg("Successful delivery", **self._client_info)
+                self.log.info("Successful delivery", **self._client_info)
             elif response.status_code == 202 or response.logged_status == 202:
-                log.msg("Router miss, message stored.", **self._client_info)
+                self.log.info("Router miss, message stored.",
+                              **self._client_info)
             time_diff = time.time() - self.start_time
             self.metrics.timing("updates.handled", duration=time_diff)
             self._router_response(response)
@@ -592,7 +592,7 @@ def post(self, router_type="", router_token="", uaid="", chid=""):
 
         # normalize the path vars into parameters
         if router_type not in self.ap_settings.routers:
-            log.msg("Invalid router requested", **self._client_info)
+            self.log.debug("Invalid router requested", **self._client_info)
             return self._write_response(
                 400, 108, message="Invalid router")
         router = self.ap_settings.routers[router_type]
@@ -645,7 +645,7 @@ def put(self, router_type="", router_token="", uaid="", chid=""):
         self.uaid = uaid
         router_data = params
         if router_type not in self.ap_settings.routers or not router_data:
-            log.msg("Invalid router requested", **self._client_info)
+            self.log.debug("Invalid router requested", **self._client_info)
             return self._write_response(
                 400, 108, message="Invalid router")
         router = self.ap_settings.routers[router_type]
@@ -693,7 +693,7 @@ def delete(self, router_type="", router_token="", uaid="", chid=""):
             return self._write_unauthorized_response(
                 message="Invalid Authentication")
         if router_type not in self.ap_settings.routers:
-            log.msg("Invalid router requested", **self._client_info)
+            self.log.debug("Invalid router requested", **self._client_info)
             return self._write_response(
                 400, 108, message="Invalid router")
         router = self.ap_settings.routers[router_type]
@@ -764,7 +764,7 @@ def _return_endpoint(self, endpoint_data, new_uaid, router=None):
         else:
             msg = dict(channelID=self.chid, endpoint=endpoint_data[0])
         self.write(json.dumps(msg))
-        log.msg("Endpoint registered via HTTP", **self._client_info)
+        self.log.debug("Endpoint registered via HTTP", **self._client_info)
         self.finish()
 
     def _success(self, result):

autopush/health.py

@@ -6,7 +6,7 @@
 )
 from twisted.internet.defer import DeferredList
 from twisted.internet.threads import deferToThread
-from twisted.python import log
+from twisted.logger import Logger
 
 from autopush import __version__
 
@@ -18,6 +18,8 @@ class MissingTableException(Exception):
 
 class HealthHandler(cyclone.web.RequestHandler):
     """HTTP Health Handler"""
+    log = Logger()
+
     @cyclone.web.asynchronous
     def get(self):
         """HTTP Get
@@ -54,7 +56,7 @@ def _check_success(self, result, name):
     def _check_error(self, failure, name):
         """Returns an error, and why"""
         self._healthy = False
-        log.err(failure, name)
+        self.log.failure(failure, name)
 
         cause = self._health_checks[name] = {"status": "NOT OK"}
         if failure.check(InternalServerError):