fix: log all drop_user calls with record details when possible

Closes #650

autopush/db.py

@@ -15,7 +15,7 @@
 )
 from boto.dynamodb2.fields import HashKey, RangeKey, GlobalKeysOnlyIndex
 from boto.dynamodb2.layer1 import DynamoDBConnection
-from boto.dynamodb2.table import Table
+from boto.dynamodb2.table import Table, Item
 from boto.dynamodb2.types import NUMBER
 
 from autopush.exceptions import AutopushException
@@ -49,6 +49,20 @@ def hasher(uaid):
     return uaid
 
 
+def dump_uaid(uaid_data):
+    """Return a dict for a uaid.
+
+    This is utilized instead of repr since some db methods return a
+    DynamoDB Item which does not actually show its dict key/values
+    when dumped via repr.
+
+    """
+    if isinstance(uaid_data, Item):
+        return repr(uaid_data.items())
+    else:
+        return repr(uaid_data)
+
+
 def normalize_id(ident):
     if (len(ident) == 36 and
             ident[8] == ident[13] == ident[18] == ident[23] == '-'):

autopush/endpoint.py

@@ -43,6 +43,7 @@
 
 from autopush.base import BaseHandler
 from autopush.db import (
+    dump_uaid,
     generate_last_connect,
     hasher,
     normalize_id,
@@ -609,6 +610,9 @@ def _router_completed(self, response, uaid_data, warning=""):
                 # An empty router_data object indicates that the record should
                 # be deleted. There is no longer valid route information for
                 # this record.
+                self.log.info(format="Dropping User", code=100,
+                              uaid_hash=hasher(self.uaid),
+                              uaid_record=dump_uaid(uaid_data))
                 d = deferToThread(self.ap_settings.router.drop_user,
                                   self.uaid)
                 d.addCallback(lambda x: self._router_response(response))
@@ -754,6 +758,8 @@ def _delete_channel(self, uaid, chid):
     def _delete_uaid(self, uaid, router):
         message = self.ap_settings.message
         message.delete_user(uaid)
+        self.log.info(format="Dropping User", code=101,
+                      uaid_hash=hasher(uaid))
         if not router.drop_user(uaid):
             raise ItemNotFound("UAID not found")
 

autopush/router/webpush.py

@@ -19,7 +19,11 @@
 from autopush.protocol import IgnoreBody
 from autopush.router.interface import RouterException, RouterResponse
 from autopush.router.simple import SimpleRouter
-from autopush.db import normalize_id
+from autopush.db import (
+    dump_uaid,
+    hasher,
+    normalize_id,
+)
 
 TTL_URL = "https://webpush-wg.github.io/webpush-protocol/#rfc.section.6.2"
 
@@ -64,16 +68,18 @@ def preflight_check(self, uaid_data, channel_id):
         """Verifies this routing call can be done successfully"""
         uaid = uaid_data["uaid"]
         if 'current_month' not in uaid_data:
-            self.log.info("Record missing 'current_month' {record}",
-                          record=repr(uaid_data))
+            self.log.info(format="Dropping User", code=102,
+                          uaid_hash=hasher(uaid),
+                          uaid_record=dump_uaid(uaid_data))
             yield deferToThread(self.ap_settings.router.drop_user, uaid)
             raise RouterException("No such subscription", status_code=410,
                                   log_exception=False, errno=106)
 
         month_table = uaid_data["current_month"]
         if month_table not in self.ap_settings.message_tables:
-            self.log.info("'current_month' out of scope: {record}",
-                          record=repr(uaid_data))
+            self.log.info(format="Dropping User", code=103,
+                          uaid_hash=hasher(uaid),
+                          uaid_record=dump_uaid(uaid_data))
             yield deferToThread(self.ap_settings.router.drop_user, uaid)
             raise RouterException("No such subscription", status_code=410,
                                   log_exception=False, errno=106)

autopush/tests/test_web_webpush.py

@@ -95,6 +95,7 @@ def test_router_returns_data_without_detail(self):
         ))
         self.fernet_mock.decrypt.return_value = dummy_token
         self.router_mock.get_uaid.return_value = dict(
+            uaid=dummy_uaid,
             router_type="webpush",
             router_data=dict(uaid="uaid"),
         )

autopush/web/webpush.py

@@ -12,7 +12,10 @@
     WebPushRequestSchema,
 )
 from autopush.websocket import ms_time
-from autopush.db import hasher
+from autopush.db import (
+    dump_uaid,
+    hasher,
+)
 
 
 class WebPushHandler(BaseWebHandler):
@@ -63,8 +66,11 @@ def _router_completed(self, response, uaid_data, warning=""):
                 # An empty router_data object indicates that the record should
                 # be deleted. There is no longer valid route information for
                 # this record.
+                self.log.info(format="Dropping User", code=100,
+                              uaid_hash=hasher(uaid_data["uaid"]),
+                              uaid_record=dump_uaid(uaid_data))
                 d = deferToThread(self.ap_settings.router.drop_user,
-                                  uaid_data["router_data"]["uaid"])
+                                  uaid_data["uaid"])
                 d.addCallback(lambda x: self._router_response(response))
                 return d
             # The router data needs to be updated to include any changes

autopush/websocket.py

@@ -65,8 +65,8 @@
 from autopush.db import (
     has_connected_this_month,
     hasher,
-    generate_last_connect
-)
+    generate_last_connect,
+    dump_uaid)
 from autopush.protocol import IgnoreBody
 from autopush.utils import (
     parse_user_agent,
@@ -711,6 +711,9 @@ def _verify_user_record(self):
         # All records must have a router_type and connected_at, in some odd
         # cases a record exists for some users that doesn't
         if "router_type" not in record or "connected_at" not in record:
+            self.log.info(format="Dropping User", code=104,
+                          uaid_hash=hasher(self.ps.uaid),
+                          uaid_record=dump_uaid(record))
             self.force_retry(self.ap_settings.router.drop_user, self.ps.uaid)
             return None
 
@@ -719,6 +722,9 @@ def _verify_user_record(self):
             # Current month must exist and be a valid prior month
             if ("current_month" not in record) or record["current_month"] \
                     not in self.ps.settings.message_tables:
+                self.log.info(format="Dropping User", code=105,
+                              uaid_hash=hasher(self.ps.uaid),
+                              uaid_record=dump_uaid(record))
                 self.force_retry(self.ap_settings.router.drop_user,
                                  self.ps.uaid)
                 return None