Merge pull request #420 from mozilla-services/feat/issue-419

feat: update logging for newstyle twisted and file output

.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):