diff --git a/autopush/db.py b/autopush/db.py index a581b748..55853787 100644 --- a/autopush/db.py +++ b/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] == '-'): diff --git a/autopush/endpoint.py b/autopush/endpoint.py index b1b51005..a9747700 100644 --- a/autopush/endpoint.py +++ b/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") diff --git a/autopush/router/webpush.py b/autopush/router/webpush.py index a3aa0cb5..816747a5 100644 --- a/autopush/router/webpush.py +++ b/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) diff --git a/autopush/tests/test_web_webpush.py b/autopush/tests/test_web_webpush.py index 477c6f6b..9e9d0d6c 100644 --- a/autopush/tests/test_web_webpush.py +++ b/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"), ) diff --git a/autopush/web/webpush.py b/autopush/web/webpush.py index d070a6bb..8b48a8a4 100644 --- a/autopush/web/webpush.py +++ b/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 diff --git a/autopush/websocket.py b/autopush/websocket.py index 5e1b3d4e..42688411 100644 --- a/autopush/websocket.py +++ b/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