bug: add logging for register/unregister calls for websocket and bridges

Closes #952

autopush/db.py

@@ -466,8 +466,8 @@ def unregister_channel(self, uaid, channel_id, **kwargs):
         conn = self.table.connection
         db_key = self.encode({"uaid": hasher(uaid), "chidmessageid": " "})
         expr = "DELETE chids :channel_id"
-        expr_values = self.encode({":channel_id":
-                                   set([normalize_id(channel_id)])})
+        chid = normalize_id(channel_id)
+        expr_values = self.encode({":channel_id": set([chid])})
 
         result = conn.update_item(
             self.table.table_name,
@@ -479,7 +479,7 @@ def unregister_channel(self, uaid, channel_id, **kwargs):
         chids = result.get('Attributes', {}).get('chids', {})
         if chids:
             try:
-                return channel_id in self.table._dynamizer.decode(chids)
+                return chid in self.table._dynamizer.decode(chids)
             except (TypeError, AttributeError):  # pragma: nocover
                 pass
         # if, for some reason, there are no chids defined, return False.

autopush/tests/test_endpoint.py

@@ -562,6 +562,21 @@ def test_put_bad_router_register(self):
         )
         self._check_error(resp, rexc.status_code, rexc.errno, "")
 
+    @inlineCallbacks
+    def test_delete_success(self):
+        notif = make_webpush_notification(dummy_uaid.hex, str(dummy_chid))
+        messages = self.db.message
+        messages.register_channel(dummy_uaid.hex, str(dummy_chid))
+        messages.store_message(notif)
+
+        yield self.client.delete(
+            self.url(router_type="test",
+                     router_token="test",
+                     uaid=dummy_uaid.hex,
+                     chid=str(dummy_chid)),
+            headers={"Authorization": self.auth},
+        )
+
     @inlineCallbacks
     def test_delete_bad_chid_value(self):
         notif = make_webpush_notification(dummy_uaid.hex, str(dummy_chid))

autopush/tests/test_websocket.py

@@ -1054,7 +1054,7 @@ def test_register(self):
         eq_(msg["status"], 200)
         eq_(msg["messageType"], "register")
         ok_("pushEndpoint" in msg)
-        assert_called_included(self.proto.log.debug, format="Register")
+        assert_called_included(self.proto.log.info, format="Register")
 
     @inlineCallbacks
     def test_register_webpush(self):
@@ -1066,7 +1066,7 @@ def test_register_webpush(self):
 
         yield self.proto.process_register(dict(channelID=chid))
         ok_(self.proto.db.message.register_channel.called)
-        assert_called_included(self.proto.log.debug, format="Register")
+        assert_called_included(self.proto.log.info, format="Register")
 
     @inlineCallbacks
     def test_register_webpush_with_key(self):
@@ -1095,7 +1095,7 @@ def echo(string):
         eq_(test_endpoint,
             self.proto.sendJSON.call_args[0][0]['pushEndpoint'])
         ok_(self.proto.db.message.register_channel.called)
-        assert_called_included(self.proto.log.debug, format="Register")
+        assert_called_included(self.proto.log.info, format="Register")
 
     @inlineCallbacks
     def test_register_no_chid(self):
@@ -1272,7 +1272,7 @@ def test_ws_unregister(self):
         eq_(msg["status"], 200)
         eq_(msg["channelID"], chid)
         eq_(len(self.proto.log.mock_calls), 2)
-        assert_called_included(self.proto.log.debug, format="Unregister")
+        assert_called_included(self.proto.log.info, format="Unregister")
 
     @inlineCallbacks
     def test_ws_unregister_without_chid(self):
@@ -1313,7 +1313,7 @@ def raise_exception(*args, **kwargs):
                                 channelID=chid))
         yield self._wait_for(lambda: self.proto.log.failure.called)
         self.proto.log.failure.assert_called_once()
-        assert_called_included(self.proto.log.debug, format="Unregister")
+        assert_called_included(self.proto.log.info, format="Unregister")
 
     def test_notification(self):
         self._connect()

autopush/web/registration.py

@@ -314,8 +314,10 @@ def _write_endpoint(self, endpoint, uaid, chid, router_type, router_data,
             router.amend_endpoint_response(response, router_data)
         self.set_header("Content-Type", "application/json")
         self.write(json.dumps(response))
-        self.log.debug("Endpoint registered via HTTP",
-                       client_info=self._client_info)
+        self.log.info("Register",
+                      client_info=self._client_info,
+                      endpoint=endpoint,
+                      uaid_hash=hasher(uaid))
         self.finish()
 
     def _success(self, result):
@@ -465,6 +467,10 @@ def delete(self, uaid, chid):
     def _delete_channel(self, uaid, chid):
         if not self.db.message.unregister_channel(uaid.hex, chid):
             raise ItemNotFound("ChannelID not found")
+        self.log.info("Unregister",
+                      client_info=self._client_info,
+                      channel_id=chid,
+                      uaid_hash=hasher(uaid))
 
     def _chid_not_found_err(self, fail):
         """errBack for unknown chid"""

autopush/websocket.py

@@ -1256,7 +1256,7 @@ def send_register_finish(self, result, endpoint, chid):
         self.sendJSON(msg)
         self.metrics.increment("ua.command.register", tags=self.base_tags)
         self.ps.stats.registers += 1
-        self.log.debug(format="Register", channel_id=chid,
+        self.log.info(format="Register", channel_id=chid,
                        endpoint=endpoint,
                        uaid_hash=self.ps.uaid_hash,
                        user_agent=self.ps.user_agent,
@@ -1281,7 +1281,7 @@ def process_unregister(self, data):
                      **self.ps.raw_agent)
         if "code" in data:
             event["code"] = extract_code(data)
-        self.log.debug(**event)
+        self.log.info(**event)
 
         # Clear out any existing tracked messages for this channel
         if self.ps.use_webpush: