feat: demote info to debug to reduce logging messages

Closes #936

autopush/router/apns2.py

@@ -94,7 +94,7 @@ def __init__(self, cert_file, key_file, topic,
                 ssl_context=self.ssl_context,
                 force_proto='h2') for x in range(0, max_connections)))
         if self.log:
-            self.log.info("Starting APNS connection")
+            self.log.debug("Starting APNS connection")
 
     def send(self, router_token, payload, apns_id,
              priority=True, topic=None, exp=None):

autopush/router/fcm.py

@@ -227,8 +227,8 @@ def _process_reply(self, reply, notification, router_data, ttl):
         if reply.get('canonical_ids'):
             old_id = router_data['token']
             new_id = result.get('registration_id')
-            self.log.info("FCM id changed : {old} => {new}",
-                          old=old_id, new=new_id)
+            self.log.debug("FCM id changed : {old} => {new}",
+                           old=old_id, new=new_id)
             self.metrics.increment("updates.client.bridge.fcm.failed.rereg",
                                    self._base_tags)
             return RouterResponse(status_code=503,
@@ -253,10 +253,10 @@ def _process_reply(self, reply, notification, router_data, ttl):
                                                     "later.",
                                       log_exception=False)
             creds = router_data["creds"]
-            self.log.info("{msg} : {info}",
-                          msg=err['msg'],
-                          info={"senderid": creds.get('registration_id'),
-                                "reason": reason})
+            self.log.debug("{msg} : {info}",
+                           msg=err['msg'],
+                           info={"senderid": creds.get('registration_id'),
+                                 "reason": reason})
             return RouterResponse(
                 status_code=err['err'],
                 errno=err['errno'],

autopush/router/gcm.py

@@ -146,8 +146,8 @@ def _process_reply(self, reply, uaid_data, ttl, notification):
         #  for reg_id, msg_id in reply.success.items():
         # updates
         for old_id, new_id in reply.canonical.items():
-            self.log.info("GCM id changed : {old} => {new}",
-                          old=old_id, new=new_id)
+            self.log.debug("GCM id changed : {old} => {new}",
+                           old=old_id, new=new_id)
             self.metrics.increment("updates.client.bridge.gcm.failed.rereg",
                                    self._base_tags)
             return RouterResponse(status_code=503,
@@ -158,7 +158,7 @@ def _process_reply(self, reply, uaid_data, ttl, notification):
         for reg_id in reply.not_registered:
             self.metrics.increment("updates.client.bridge.gcm.failed.unreg",
                                    self._base_tags)
-            self.log.info("GCM no longer registered: %s" % reg_id)
+            self.log.debug("GCM no longer registered: %s" % reg_id)
             return RouterResponse(
                 status_code=410,
                 response_body="Endpoint requires client update",
@@ -169,8 +169,8 @@ def _process_reply(self, reply, uaid_data, ttl, notification):
         if len(reply.failed.items()) > 0:
             self.metrics.increment("updates.client.bridge.gcm.failed.failure",
                                    self._base_tags)
-            self.log.info("GCM failures: {failed()}",
-                          failed=lambda: repr(reply.failed.items()))
+            self.log.debug("GCM failures: {failed()}",
+                           failed=lambda: repr(reply.failed.items()))
             raise RouterException("GCM unable to deliver", status_code=410,
                                   response_body="GCM recipient not available.",
                                   log_exception=False,

autopush/tests/test_websocket.py

@@ -1065,7 +1065,7 @@ def test_register(self):
         eq_(msg["status"], 200)
         eq_(msg["messageType"], "register")
         ok_("pushEndpoint" in msg)
-        assert_called_included(self.proto.log.info, format="Register")
+        assert_called_included(self.proto.log.debug, format="Register")
 
     @inlineCallbacks
     def test_register_webpush(self):
@@ -1077,7 +1077,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.info, format="Register")
+        assert_called_included(self.proto.log.debug, format="Register")
 
     @inlineCallbacks
     def test_register_webpush_with_key(self):
@@ -1106,7 +1106,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.info, format="Register")
+        assert_called_included(self.proto.log.debug, format="Register")
 
     @inlineCallbacks
     def test_register_no_chid(self):
@@ -1289,7 +1289,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.info, format="Unregister")
+        assert_called_included(self.proto.log.debug, format="Unregister")
 
     @inlineCallbacks
     def test_ws_unregister_without_chid(self):
@@ -1330,7 +1330,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.info, format="Unregister")
+        assert_called_included(self.proto.log.debug, format="Unregister")
 
     def test_notification(self):
         self._connect()
@@ -1420,8 +1420,8 @@ def test_ack(self):
 
         # Verify it was cleared out
         eq_(len(self.proto.ps.direct_updates), 0)
-        eq_(len(self.proto.log.info.mock_calls), 2)
-        assert_called_included(self.proto.log.info,
+        eq_(len(self.proto.log.debug.mock_calls), 2)
+        assert_called_included(self.proto.log.debug,
                                format="Ack",
                                router_key="simplepush",
                                message_source="direct",
@@ -1446,8 +1446,8 @@ def test_ack_with_webpush_direct(self):
             version=dummy_version
         ))
         eq_(self.proto.ps.direct_updates[chid], [])
-        eq_(len(self.proto.log.info.mock_calls), 1)
-        assert_called_included(self.proto.log.info,
+        eq_(len(self.proto.log.debug.mock_calls), 1)
+        assert_called_included(self.proto.log.debug,
                                format="Ack",
                                router_key="webpush",
                                message_source="direct",
@@ -1472,8 +1472,8 @@ def test_ack_with_webpush_from_storage(self):
         ))
         ok_(self.proto.force_retry.called)
         ok_(mock_defer.addBoth.called)
-        eq_(len(self.proto.log.info.mock_calls), 1)
-        assert_called_included(self.proto.log.info,
+        eq_(len(self.proto.log.debug.mock_calls), 1)
+        assert_called_included(self.proto.log.debug,
                                format="Ack",
                                router_key="webpush",
                                message_source="stored")
@@ -1486,7 +1486,7 @@ def test_nack(self):
             version=dummy_version,
             code=200
         )), False)
-        eq_(len(self.proto.log.info.mock_calls), 1)
+        eq_(len(self.proto.log.debug.mock_calls), 1)
 
     def test_nack_no_version(self):
         self._connect()
@@ -1495,7 +1495,7 @@ def test_nack_no_version(self):
             messageType="nack",
             code=200
         )), False)
-        eq_(len(self.proto.log.info.mock_calls), 0)
+        eq_(len(self.proto.log.debug.mock_calls), 0)
 
     def test_ack_remove(self):
         self._connect()

autopush/web/base.py

@@ -210,10 +210,10 @@ def _validation_err(self, fail):
         """errBack for validation errors"""
         fail.trap(InvalidRequest)
         exc = fail.value
-        self.log.info(format="Request validation error: {}".format(exc),
-                      status_code=exc.status_code,
-                      errno=exc.errno,
-                      client_info=self._client_info)
+        self.log.debug(format="Request validation error: {}".format(exc),
+                       status_code=exc.status_code,
+                       errno=exc.errno,
+                       client_info=self._client_info)
 
         self._write_response(exc.status_code, exc.errno,
                              message="Request did not validate %s" %
@@ -237,17 +237,17 @@ def _response_err(self, fail):
     def _overload_err(self, fail):
         """errBack for throughput provisioned exceptions"""
         fail.trap(ProvisionedThroughputExceededException)
-        self.log.info(format="Throughput Exceeded", status_code=503,
-                      errno=201, client_info=self._client_info)
+        self.log.debug(format="Throughput Exceeded", status_code=503,
+                       errno=201, client_info=self._client_info)
         self._write_response(503, 201,
                              message="Please slow message send rate")
 
     def _boto_err(self, fail):
         """errBack for random boto exceptions"""
         fail.trap(BotoServerError)
-        self.log.info(format="BOTO Error: %s" % str(fail.value),
-                      status_code=503, errno=202,
-                      client_info=self._client_info)
+        self.log.debug(format="BOTO Error: %s" % str(fail.value),
+                       status_code=503, errno=202,
+                       client_info=self._client_info)
         self._write_response(503, errno=202,
                              message="Communication error, please retry")
 
@@ -280,15 +280,15 @@ def _router_fail_err(self, fail):
                     errno=exc.errno or 0,
                     client_info=self._client_info)  # pragma nocover
             if 200 <= exc.status_code < 300:
-                self.log.info(format="Success", status_code=exc.status_code,
-                              logged_status=exc.logged_status or 0,
-                              client_info=self._client_info)
+                self.log.debug(format="Success", status_code=exc.status_code,
+                               logged_status=exc.logged_status or 0,
+                               client_info=self._client_info)
             elif 400 <= exc.status_code < 500:
-                self.log.info(format="Client error",
-                              status_code=exc.status_code,
-                              logged_status=exc.logged_status or 0,
-                              errno=exc.errno or 0,
-                              client_info=self._client_info)
+                self.log.debug(format="Client error",
+                               status_code=exc.status_code,
+                               logged_status=exc.logged_status or 0,
+                               errno=exc.errno or 0,
+                               client_info=self._client_info)
         self._router_response(exc)
 
     def _write_validation_err(self, errors):
@@ -323,5 +323,5 @@ def _track_timing(self, status_code=None):
         """
         status_code = status_code or self.get_status()
         self._timings["request_time"] = time.time() - self._start_time
-        self.log.info("Request timings", client_info=self._client_info,
-                      timings=self._timings, status_code=status_code)
+        self.log.debug("Request timings", client_info=self._client_info,
+                       timings=self._timings, status_code=status_code)

autopush/web/message.py

@@ -46,7 +46,7 @@ def delete(self, notification):
         return d
 
     def _delete_completed(self, *args, **kwargs):
-        self.log.info(format="Message Deleted", status_code=204,
-                      **self._client_info)
+        self.log.debug(format="Message Deleted", status_code=204,
+                       **self._client_info)
         self.set_status(204)
         self.finish()

autopush/web/registration.py

@@ -409,17 +409,17 @@ def delete(self, uaid):
         return d
 
     def _delete_uaid(self, uaid):
-        self.log.info(format="Dropping User", code=101,
-                      uaid_hash=hasher(uaid.hex))
+        self.log.debug(format="Dropping User", code=101,
+                       uaid_hash=hasher(uaid.hex))
         if not self.db.router.drop_user(uaid.hex):
             raise ItemNotFound("UAID not found")
 
     def _uaid_not_found_err(self, fail):
         """errBack for uaid lookup not finding the user"""
         fail.trap(ItemNotFound)
-        self.log.info(format="UAID not found in AWS.",
-                      status_code=410, errno=103,
-                      client_info=self._client_info)
+        self.log.debug(format="UAID not found in AWS.",
+                       status_code=410, errno=103,
+                       client_info=self._client_info)
         self._write_response(410, errno=103,
                              message="Endpoint has expired. "
                                      "Do not send messages to this endpoint.")
@@ -470,7 +470,7 @@ def _delete_channel(self, uaid, chid):
     def _chid_not_found_err(self, fail):
         """errBack for unknown chid"""
         fail.trap(ItemNotFound, ValueError)
-        self.log.info(format="CHID not found in AWS.",
-                      status_code=410, errno=106,
-                      **self._client_info)
+        self.log.debug(format="CHID not found in AWS.",
+                       status_code=410, errno=106,
+                       **self._client_info)
         self._write_response(410, 106, message="Invalid endpoint.")

autopush/web/simplepush.py

@@ -129,11 +129,11 @@ def put(self, subscription, version, data):
     def _router_completed(self, response, uaid_data, warning=""):
         """Called after router has completed successfully"""
         if response.status_code == 200 or response.logged_status == 200:
-            self.log.info(format="Successful delivery",
-                          client_info=self._client_info)
+            self.log.debug(format="Successful delivery",
+                           client_info=self._client_info)
         elif response.status_code == 202 or response.logged_status == 202:
-            self.log.info(format="Router miss, message stored.",
-                          client_info=self._client_info)
+            self.log.debug(format="Router miss, message stored.",
+                           client_info=self._client_info)
         time_diff = time.time() - self._start_time
         self.metrics.timing("updates.handled", duration=time_diff)
         response.response_body = (

autopush/web/webpush.py

@@ -26,6 +26,7 @@
 
 from autopush.crypto_key import CryptoKey
 from autopush.db import DatabaseManager  # noqa
+from autopush.metrics import Metrics  # noqa
 from autopush.db import dump_uaid, hasher
 from autopush.exceptions import (
     InvalidRequest,
@@ -109,30 +110,33 @@ def validate_uaid_month_and_chid(self, d):
     def _validate_webpush(self, d, result):
         db = self.context["db"]  # type: DatabaseManager
         log = self.context["log"]  # type: Logger
+        metrics = self.context["metrics"]  # type: Metrics
         channel_id = normalize_id(d["chid"])
         uaid = result["uaid"]
         if 'current_month' not in result:
-            log.info(format="Dropping User", code=102,
-                     uaid_hash=hasher(uaid),
-                     uaid_record=dump_uaid(result))
+            log.debug(format="Dropping User", code=102,
+                      uaid_hash=hasher(uaid),
+                      uaid_record=dump_uaid(result))
+            metrics.increment("updates.drop_user", tags={"errno": 102})
             db.router.drop_user(uaid)
             raise InvalidRequest("No such subscription", status_code=410,
                                  errno=106)
 
         month_table = result["current_month"]
         if month_table not in db.message_tables:
-            log.info(format="Dropping User", code=103,
-                     uaid_hash=hasher(uaid),
-                     uaid_record=dump_uaid(result))
+            log.debug(format="Dropping User", code=103,
+                      uaid_hash=hasher(uaid),
+                      uaid_record=dump_uaid(result))
+            metrics.increment("updates.drop_user", tags={"errno": 103})
             db.router.drop_user(uaid)
             raise InvalidRequest("No such subscription", status_code=410,
                                  errno=106)
         exists, chans = db.message_tables[month_table].all_channels(uaid=uaid)
 
         if (not exists or channel_id.lower() not
                 in map(lambda x: normalize_id(x), chans)):
-            log.info("Unknown subscription: {channel_id}",
-                     channel_id=channel_id)
+            log.debug("Unknown subscription: {channel_id}",
+                      channel_id=channel_id)
             raise InvalidRequest("No such subscription", status_code=410,
                                  errno=106)
 
@@ -481,10 +485,10 @@ 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),
-                              client_info=self._client_info)
+                self.log.debug(format="Dropping User", code=100,
+                               uaid_hash=hasher(uaid_data["uaid"]),
+                               uaid_record=dump_uaid(uaid_data),
+                               client_info=self._client_info)
                 d = deferToThread(self.db.router.drop_user, uaid_data["uaid"])
                 d.addCallback(lambda x: self._router_response(response))
                 return d
@@ -503,10 +507,10 @@ def _router_completed(self, response, uaid_data, warning=""):
         else:
             # No changes are requested by the bridge system, proceed as normal
             if response.status_code == 200 or response.logged_status == 200:
-                self.log.info(format="Successful delivery",
-                              client_info=self._client_info)
+                self.log.debug(format="Successful delivery",
+                               client_info=self._client_info)
             elif response.status_code == 202 or response.logged_status == 202:
-                self.log.info(
+                self.log.debug(
                     format="Router miss, message stored.",
                     client_info=self._client_info)
             self.metrics.timing("updates.handled", duration=time_diff)