feat: Add endpoint to test logging

call /v1/err (or /v1/err/error) to invoke a fake "error" for testing purposes.
call /v1/err/critical to invoke a fake critical exception.
Responds with a status of 418 and creates an appropriate log entry.

Closes #478

autopush/endpoint.py

@@ -191,13 +191,14 @@ def _init_info(self):
     #############################################################
     #                    Error Callbacks
     #############################################################
-    def _write_response(self, status_code, errno, message=None, headers=None):
+    def _write_response(self, status_code, errno, message=None, headers=None,
+                        reason=None):
         """Writes out a full JSON error and sets the appropriate status"""
-        self.set_status(status_code)
+        self.set_status(status_code, reason)
         error_data = dict(
             code=status_code,
             errno=errno,
-            error=status_codes.get(status_code, "")
+            error=status_codes.get(status_code, reason or "")
         )
         if message:
             error_data["message"] = message

autopush/log_check.py

@@ -0,0 +1,44 @@
+import uuid
+
+import cyclone.web
+
+from autopush.endpoint import AutoendpointHandler
+
+
+class LogCheckError(Exception):
+    pass
+
+
+class LogCheckHandler(AutoendpointHandler):
+
+    def initialize(self, ap_settings):
+        self.ap_settings = ap_settings
+        self.request_id = str(uuid.uuid4())
+        self._client_info = self._init_info()
+
+    @cyclone.web.asynchronous
+    def get(self, errType=None):
+        """HTTP GET
+
+        Generate a dummy error message for logging
+
+        """
+        if not errType:
+            errType = "error"
+        else:
+            errType = errType.lower()
+        if 'error' in errType:
+            self.log.error(format="Test Error Message",
+                           status_code=418, errno=0,
+                           **self._client_info)
+            self._write_response(418, 999, message="ERROR:Success",
+                                 reason="Test Error")
+        if 'crit' in errType:
+            try:
+                raise LogCheckError("LogCheck")
+            except:
+                self.log.failure(format="Test Critical Message",
+                                 status_code=418, errno=0,
+                                 **self._client_info)
+                self._write_response(418, 999, message="FAILURE:Success",
+                                     reason="Test Failure")

autopush/main.py

@@ -16,6 +16,7 @@
     MessageHandler,
     RegistrationHandler,
 )
+from autopush.log_check import LogCheckHandler
 from autopush.health import (HealthHandler, StatusHandler)
 from autopush.logging import PushLogger
 from autopush.settings import AutopushSettings
@@ -509,6 +510,8 @@ def endpoint_main(sysargs=None, use_files=True):
             "?(?:/subscription)?(?:/([^\/]+))?",
          RegistrationHandler,
          dict(ap_settings=settings)),
+        (r"/v1/err(?:/([^\/]+))?", LogCheckHandler,
+            dict(ap_settings=settings)),
     ],
         default_host=settings.hostname, debug=args.debug,
         log_function=skip_request_logging

autopush/tests/test_endpoint.py

@@ -95,7 +95,7 @@ def test_delete_token_invalid(self):
             "decrypt.side_effect": InvalidToken})
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.message.delete('')
@@ -105,7 +105,7 @@ def test_delete_token_wrong_components(self):
         self.fernet_mock.decrypt.return_value = "123:456"
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.message.delete('')
@@ -115,7 +115,7 @@ def test_delete_token_wrong_kind(self):
         self.fernet_mock.decrypt.return_value = "r:123:456"
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.message.delete('')
@@ -143,7 +143,7 @@ def test_delete_db_error(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.status_mock.assert_called_with(503)
+            self.status_mock.assert_called_with(503, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.message.delete('')
@@ -248,7 +248,7 @@ def test_uaid_lookup_results_bad_ttl(self):
         self.endpoint._uaid_lookup_results(fresult)
 
         def handle_finish(value):
-            self.endpoint.set_status.assert_called_with(400)
+            self.endpoint.set_status.assert_called_with(400, None)
 
         self.finish_deferred.addCallback(handle_finish)
         return self.finish_deferred
@@ -314,7 +314,7 @@ def raise_error(*args):
 
         def handle_finish(result):
             self.flushLoggedErrors()
-            self.endpoint.set_status.assert_called_with(400)
+            self.endpoint.set_status.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.post(None, dummy_uaid)
@@ -341,7 +341,7 @@ def test_webpush_bad_routertype(self):
         self.request_mock.body = b"stuff"
         self.endpoint._uaid_lookup_results(fresult)
 
-        self.endpoint.set_status.assert_called_with(400)
+        self.endpoint.set_status.assert_called_with(400, None)
         data = self.write_mock.call_args[0][0]
         d = json.loads(data)
         eq_(d.get("errno"), 108)
@@ -356,7 +356,7 @@ def test_webpush_uaid_lookup_no_crypto_headers_with_data(self):
         self.endpoint._uaid_lookup_results(fresult)
 
         def handle_finish(value):
-            self.endpoint.set_status.assert_called_with(400)
+            self.endpoint.set_status.assert_called_with(400, None)
 
         self.finish_deferred.addCallback(handle_finish)
         return self.finish_deferred
@@ -502,7 +502,7 @@ def test_put_data_too_large(self):
         self.endpoint.request.body = b'version=1&data=1234'
 
         def handle_finish(result):
-            self.endpoint.set_status.assert_called_with(413)
+            self.endpoint.set_status.assert_called_with(413, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.put(None, '')
@@ -527,7 +527,7 @@ def test_put_v1_token_as_v0_token(self):
             '\xcb\n<\x0c\xe6\xf3C4:\xa8\xaeO\xf5\xab\xfbb|'
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.put(None, '')
@@ -539,7 +539,7 @@ def test_put_token_invalid(self):
         self.endpoint.request.body = b'version=123&data=bad-token'
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.put(None, '')
@@ -550,7 +550,7 @@ def test_put_token_wrong(self):
         self.endpoint.request.body = b'version=123'
 
         def handle_finish(result):
-            self.status_mock.assert_called_with(400)
+            self.status_mock.assert_called_with(400, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.put(None, '')
@@ -568,7 +568,7 @@ def test_process_token_client_unknown(self):
 
         def handle_finish(result):
             self.router_mock.get_uaid.assert_called_with('123')
-            self.status_mock.assert_called_with(410)
+            self.status_mock.assert_called_with(410, None)
             self._check_error(410, 103, "")
         self.finish_deferred.addCallback(handle_finish)
 
@@ -626,7 +626,7 @@ def test_put_router_needs_change(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(500)
+            self.endpoint.set_status.assert_called_with(500, None)
             assert(self.router_mock.register_user.called)
         self.finish_deferred.addCallback(handle_finish)
 
@@ -646,7 +646,7 @@ def test_put_router_needs_update(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(503)
+            self.endpoint.set_status.assert_called_with(503, None)
             assert(self.router_mock.register_user.called)
         self.finish_deferred.addCallback(handle_finish)
 
@@ -671,7 +671,7 @@ def test_put_bogus_headers(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(400)
+            self.endpoint.set_status.assert_called_with(400, None)
 
         self.finish_deferred.addBoth(handle_finish)
         self.endpoint.put(None, dummy_uaid)
@@ -695,7 +695,7 @@ def test_put_invalid_vapid_crypto_header(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(400)
+            self.endpoint.set_status.assert_called_with(400, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.endpoint.put(None, dummy_uaid)
@@ -719,7 +719,7 @@ def test_put_invalid_vapid_crypto_key(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.endpoint.put(None, dummy_uaid)
@@ -743,7 +743,7 @@ def test_put_invalid_vapid_auth_header(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.endpoint.put(None, dummy_uaid)
@@ -900,7 +900,7 @@ def test_post_webpush_with_bad_vapid_auth(self):
         )
 
         def handle_finish(result):
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
             eq_(self.endpoint._client_info.get('jwt'), None)
             self.assertTrue(result)
 
@@ -936,7 +936,7 @@ def test_post_webpush_no_sig(self):
         def handle_finish(result):
             eq_(self.endpoint._client_info.get('jwt'), None)
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
 
@@ -983,7 +983,7 @@ def test_post_webpush_bad_sig(self):
         def handle_finish(result):
             eq_(self.endpoint._client_info.get('jwt'), None)
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.endpoint.post(None, dummy_uaid)
@@ -1015,7 +1015,7 @@ def test_post_webpush_bad_exp(self):
         def handle_finish(result):
             eq_(self.endpoint._client_info.get('jwt'), None)
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(401)
+            self.endpoint.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.endpoint.post(None, dummy_uaid)
@@ -1125,7 +1125,7 @@ def raise_error(*args):
 
         def handle_finish(result):
             self.flushLoggedErrors()
-            self.endpoint.set_status.assert_called_with(503)
+            self.endpoint.set_status.assert_called_with(503, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.post(None, dummy_uaid)
@@ -1137,7 +1137,7 @@ def test_put_db_error(self):
 
         def handle_finish(result):
             self.assertTrue(result)
-            self.endpoint.set_status.assert_called_with(503)
+            self.endpoint.set_status.assert_called_with(503, None)
         self.finish_deferred.addCallback(handle_finish)
 
         self.endpoint.put(None, dummy_uaid)
@@ -1221,7 +1221,7 @@ def test_write_error_no_exc(self):
         self.assertTrue(self.endpoint.log.called)
 
     def _assert_error_response(self, result):
-        self.status_mock.assert_called_with(500)
+        self.status_mock.assert_called_with(500, None)
 
     def test_padding(self):
         # Some values can't be padded and still decode.
@@ -1833,7 +1833,7 @@ def test_delete_bad_uaid(self):
         self.reg.request.headers["Authorization"] = self.auth
 
         def handle_finish(value):
-            self.reg.set_status.assert_called_with(401)
+            self.reg.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.reg.delete("test", "test", "invalid")
@@ -1843,7 +1843,7 @@ def test_delete_orphans(self):
         self.reg.request.headers["Authorization"] = self.auth
 
         def handle_finish(value):
-            self.reg.set_status.assert_called_with(410)
+            self.reg.set_status.assert_called_with(410, None)
 
         self.router_mock.drop_user = Mock()
         self.router_mock.drop_user.return_value = False
@@ -1855,7 +1855,7 @@ def test_delete_bad_auth(self, *args):
         self.reg.request.headers["Authorization"] = "Invalid"
 
         def handle_finish(value):
-            self.reg.set_status.assert_called_with(401)
+            self.reg.set_status.assert_called_with(401, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.reg.delete("test", "test", dummy_uaid)
@@ -1865,7 +1865,7 @@ def test_delete_bad_router(self):
         self.reg.request.headers['Authorization'] = self.auth
 
         def handle_finish(value):
-            self.reg.set_status.assert_called_with(400)
+            self.reg.set_status.assert_called_with(400, None)
 
         self.finish_deferred.addCallback(handle_finish)
         self.reg.delete("invalid", "test", dummy_uaid)