diff --git a/autopush/endpoint.py b/autopush/endpoint.py index 56feeaa5..3e3ba3f9 100644 --- a/autopush/endpoint.py +++ b/autopush/endpoint.py @@ -219,14 +219,16 @@ def _response_err(self, fail): running. """ - self.log.failure(fail, status_code=500, errno=999, **self._client_info) + format = fail.value.message or 'Exception' + self.log.failure(format=format, failure=fail, + status_code=500, errno=999, **self._client_info) self._write_response(500, 999) def _overload_err(self, fail): """errBack for throughput provisioned exceptions""" fail.trap(ProvisionedThroughputExceededException) - self.log.info("Throughput Exceeded", status_code=503, errno=201, - **self._client_info) + self.log.info(format="Throughput Exceeded", status_code=503, + errno=201, **self._client_info) self._write_response(503, 201) def _router_response(self, response): @@ -249,15 +251,18 @@ def _router_fail_err(self, fail): exc = fail.value if isinstance(exc, RouterException): if exc.log_exception or exc.status_code >= 500: - self.log.failure(fail, status_code=exc.status_code, + format = fail.value.message or 'Exception' + self.log.failure(format=format, + failure=fail, status_code=exc.status_code, errno=exc.errno or "", **self._client_info) # pragma nocover if 200 <= exc.status_code < 300: - self.log.info("Success", status_code=exc.status_code, + self.log.info(format="Success", status_code=exc.status_code, logged_status=exc.logged_status or "", **self._client_info) elif 400 <= exc.status_code < 500: - self.log.info("Client error", status_code=exc.status_code, + self.log.info(format="Client error", + status_code=exc.status_code, logged_status=exc.logged_status or "", errno=exc.errno or "", **self._client_info) @@ -266,21 +271,23 @@ def _router_fail_err(self, fail): def _uaid_not_found_err(self, fail): """errBack for uaid lookup not finding the user""" fail.trap(ItemNotFound) - self.log.debug("UAID not found in AWS.", status_code=410, errno=103, + self.log.debug(format="UAID not found in AWS.", + status_code=410, errno=103, **self._client_info) self._write_response(410, 103) def _token_err(self, fail): """errBack for token decryption fail""" fail.trap(InvalidToken, InvalidTokenException) - self.log.debug("Invalid token", status_code=400, errno=102, + self.log.debug(format="Invalid token", + status_code=400, errno=102, **self._client_info) self._write_response(400, 102) def _auth_err(self, fail): """errBack for invalid auth token""" fail.trap(VapidAuthException) - self.log.debug("Invalid Auth token", + self.log.debug(format="Invalid Auth token", status_code=401, errno=109, **self._client_info) @@ -289,7 +296,7 @@ def _auth_err(self, fail): def _chid_not_found_err(self, fail): """errBack for unknown chid""" fail.trap(ItemNotFound, ValueError) - self.log.debug("CHID not found in AWS.", + self.log.debug(format="CHID not found in AWS.", status_code=410, errno=106, **self._client_info) self._write_response(410, 106) @@ -319,7 +326,7 @@ def _invalid_auth(self, fail): message = fail.value.message or repr(fail.value) if isinstance(fail.value, AssertionError): message = "A decryption error occurred" - self.log.debug("Invalid bearer token: " + repr(message), + self.log.debug(format="Invalid bearer token: " + repr(message), **self._client_info) raise VapidAuthException("Invalid bearer token: " + repr(message)) @@ -393,7 +400,8 @@ def _delete_message(self, kind, uaid, chid): return d def _delete_completed(self, response): - self.log.info("Message Deleted", status_code=204, **self._client_info) + self.log.info(format="Message Deleted", status_code=204, + **self._client_info) self.set_status(204) self.finish() @@ -424,9 +432,9 @@ def put(self, api_ver="v0", token=None): crypto_key_header = self.request.headers.get('crypto-key') content_encoding = self.request.headers.get('content-encoding', "") if content_encoding.lower() == 'aesgcm128' and crypto_key_header: - self.log.debug("Invalid crypto state; aesgcm128 + Crypto-Key", - status_code=400, errno=110, - **self._client_info) + self.log.debug( + format="Invalid crypto state; aesgcm128 + Crypto-Key", + status_code=400, errno=110, **self._client_info) wpe_url = ("https://developers.google.com/web/updates/2016/03/" "web-push-encryption") self._write_response( @@ -468,8 +476,9 @@ def _uaid_lookup_results(self, result): try: self.router = self.ap_settings.routers[router_key] except KeyError: - self.log.debug("Invalid router requested", status_code=400, - errno=108, **self._client_info) + self.log.debug( + format="Invalid router requested", status_code=400, + errno=108, **self._client_info) return self._write_response(400, 108, message="Invalid router") @@ -487,13 +496,13 @@ def _uaid_lookup_results(self, result): req_fields = ["content-encoding", "encryption"] if data and not all([x in self.request.headers for x in req_fields]): - self.log.debug("Client error", status_code=400, errno=101, - **self._client_info) + self.log.debug(format="Client error", status_code=400, + errno=101, **self._client_info) return self._write_response(400, 101) if ("encryption-key" in self.request.headers and "crypto-key" in self.request.headers): - self.log.debug("Client error", status_code=400, errno=110, - **self._client_info) + self.log.debug(format="Client error", status_code=400, + errno=110, **self._client_info) return self._write_response( 400, 110, message="Invalid crypto headers") self._client_info["message_size"] = len(data) if data else 0 @@ -505,12 +514,12 @@ def _uaid_lookup_results(self, result): # Cap the TTL to our MAX_TTL ttl = min(ttl, MAX_TTL) else: - self.log.debug("Client error", status_code=400, + self.log.debug(format="Client error", status_code=400, errno=112, **self._client_info) return self._write_response(400, 112, message="Invalid TTL header") if data and len(data) > self.ap_settings.max_data: - self.log.debug("Client error", status_code=400, errno=104, + self.log.debug(format="Client error", status_code=400, errno=104, **self._client_info) return self._write_response( 413, 104, message="Data payload too large") @@ -574,9 +583,10 @@ def _router_completed(self, response, uaid_data, warning=""): return d else: if response.status_code == 200 or response.logged_status == 200: - self.log.info("Successful delivery", **self._client_info) + self.log.info(format="Successful delivery", + **self._client_info) elif response.status_code == 202 or response.logged_status == 202: - self.log.info("Router miss, message stored.", + self.log.info(format="Router miss, message stored.", **self._client_info) time_diff = time.time() - self.start_time self.metrics.timing("updates.handled", duration=time_diff) @@ -631,7 +641,7 @@ def post(self, router_type="", router_token="", uaid="", chid=""): # normalize the path vars into parameters if router_type not in self.ap_settings.routers: - self.log.debug("Invalid router requested", + self.log.debug(format="Invalid router requested", status_code=400, errno=108, **self._client_info) return self._write_response( @@ -687,7 +697,7 @@ def put(self, router_type="", router_token="", uaid="", chid=""): self.uaid = uaid router_data = params if router_type not in self.ap_settings.routers or not router_data: - self.log.debug("Invalid router requested", status_code=400, + self.log.debug(format="Invalid router requested", status_code=400, errno=108, **self._client_info) return self._write_response( 400, 108, message="Invalid router") @@ -737,7 +747,7 @@ def delete(self, router_type="", router_token="", uaid="", chid=""): return self._write_unauthorized_response( message="Invalid Authentication") if router_type not in self.ap_settings.routers: - self.log.debug("Invalid router requested", + self.log.debug(format="Invalid router requested", status_code=400, errno=108, **self._client_info) return self._write_response( @@ -810,7 +820,8 @@ def _return_endpoint(self, endpoint_data, new_uaid, router=None): else: msg = dict(channelID=self.chid, endpoint=endpoint_data[0]) self.write(json.dumps(msg)) - self.log.debug("Endpoint registered via HTTP", **self._client_info) + self.log.debug(format="Endpoint registered via HTTP", + **self._client_info) self.finish() def _success(self, result): diff --git a/autopush/health.py b/autopush/health.py index 00a88f4a..37e6c79b 100644 --- a/autopush/health.py +++ b/autopush/health.py @@ -56,7 +56,8 @@ def _check_success(self, result, name): def _check_error(self, failure, name): """Returns an error, and why""" self._healthy = False - self.log.failure(failure, name) + format = failure.value.message or "Heath Exception" + self.log.failure(format=format, failure=failure, name=name) cause = self._health_checks[name] = {"status": "NOT OK"} if failure.check(InternalServerError): diff --git a/autopush/logging.py b/autopush/logging.py index 1f3cfa38..a7c52f69 100644 --- a/autopush/logging.py +++ b/autopush/logging.py @@ -91,7 +91,7 @@ def __call__(self, event): f = event["failure"] reactor.callFromThread( self.raven_client.captureException, - (f.type, f.value, f.getTracebackObject()) + exc_info=(f.type, f.value, f.getTracebackObject()) ) text = self.format_event(event) @@ -124,8 +124,11 @@ def json_format(self, event): "Logger": self.logger_name, } # Add the nicely formatted message - msg["Fields"]["message"] = formatEvent(event) + try: + msg["Fields"]["message"] = formatEvent(event) + except Exception as exp: + msg["Fields"]["message"] = {"format_error": repr(exp)} return json.dumps(msg, skipkeys=True) + "\n" def start(self): diff --git a/autopush/main.py b/autopush/main.py index fbf21695..9b26f47d 100644 --- a/autopush/main.py +++ b/autopush/main.py @@ -306,7 +306,7 @@ def make_settings(args, **kwargs): # unaccounted. senderID = senderIDs.choose_ID() if senderID is None: - log.critical("No GCM SenderIDs specified or found.") + log.critical(format="No GCM SenderIDs specified or found.") return router_conf["gcm"] = {"ttl": args.gcm_ttl, "dryrun": args.gcm_dryrun, @@ -468,7 +468,7 @@ def endpoint_main(sysargs=None, use_files=True): try: senderid_list = json.loads(args.senderid_list) except (ValueError, TypeError): - log.critical("Invalid JSON specified for senderid_list") + log.critical(format="Invalid JSON specified for senderid_list") return log_level = args.log_level or ("debug" if args.debug else "info") diff --git a/autopush/senderids.py b/autopush/senderids.py index 8d094d79..d09b4889 100644 --- a/autopush/senderids.py +++ b/autopush/senderids.py @@ -59,14 +59,16 @@ def __init__(self, args): self.service = LoopingCall(self._refresh) if senderIDs: if type(senderIDs) is not dict: - self.log.critical("senderid_list is not a dict. Ignoring") + self.log.critical( + format="senderid_list is not a dict. Ignoring") else: # We're initializing, so it's ok to block. self.update(senderIDs) def start(self): if self._use_s3: - self.log.debug("Starting SenderID service...") + self.log.debug( + format="Starting SenderID service...") self.service.start(self._expry) def _write(self, senderIDs, *args): @@ -94,8 +96,9 @@ def _update_senderIDs(self, *args): candidates = json.loads(key.get_contents_as_string()) if candidates: if type(candidates) is not dict: - self.log.critical("Wrong data type stored for senderIDs. " - "Should be dict. Ignoring.") + self.log.critical( + format=("Wrong data type stored for senderIDs. " + "Should be dict. Ignoring.")) return return candidates @@ -117,7 +120,8 @@ def update(self, senderIDs): if not senderIDs: return if type(senderIDs) is not dict: - self.log.critical("Wrong data type for senderIDs. Should be dict.") + self.log.critical( + format="Wrong data type for senderIDs. Should be dict.") return if not self._use_s3: # Skip using s3 (For debugging) @@ -149,5 +153,6 @@ def choose_ID(self): def stop(self): if self.service and self.service.running: - self.log.debug("Stopping SenderID service...") + self.log.debug( + format="Stopping SenderID service...") self.service.stop() diff --git a/autopush/tests/test_endpoint.py b/autopush/tests/test_endpoint.py index 77b146b9..1d34b234 100644 --- a/autopush/tests/test_endpoint.py +++ b/autopush/tests/test_endpoint.py @@ -1065,7 +1065,7 @@ def handle_finish(result): self.endpoint.set_header.assert_called_with( "Location", "Somewhere") args, kwargs = self.endpoint.log.info.call_args - eq_("Successful delivery", args[0]) + eq_("Successful delivery", kwargs.get('format') or args[0]) self.finish_deferred.addCallback(handle_finish) self.endpoint.post(None, dummy_uaid) @@ -1092,7 +1092,8 @@ def handle_finish(result): self.endpoint.set_header.assert_called_with( "Location", "Somewhere") args, kwargs = self.endpoint.log.info.call_args - eq_("Router miss, message stored.", args[0]) + eq_("Router miss, message stored.", + kwargs.get('format') or args[0]) self.finish_deferred.addCallback(handle_finish) self.endpoint.post(None, dummy_uaid) diff --git a/autopush/tests/test_logging.py b/autopush/tests/test_logging.py index 3a8a81d1..3fa8126e 100644 --- a/autopush/tests/test_logging.py +++ b/autopush/tests/test_logging.py @@ -93,6 +93,20 @@ def test_firehose_only_output(self, mock_boto3): eq_(len(obj.firehose.mock_calls), 3) eq_(len(obj.firehose.process.mock_calls), 1) + @patch("autopush.logging.formatEvent") + def test_bad_format(self, mock_format): + + def raise_exc(*args, **kwargs): + raise Exception('Oops') + + obj = PushLogger.setup_logging("Autopush") + obj._output = mock_stdout = Mock() + mock_format.side_effect = raise_exc + log.info("omg!", Type=7) + eq_(len(mock_stdout.mock_calls), 2) + kwargs = mock_stdout.mock_calls[0][1][0] + ok_("format_error" in kwargs) + class FirehoseProcessorTestCase(twisted.trial.unittest.TestCase): def setUp(self): diff --git a/autopush/tests/test_websocket.py b/autopush/tests/test_websocket.py index 2089982d..183c4a21 100644 --- a/autopush/tests/test_websocket.py +++ b/autopush/tests/test_websocket.py @@ -1326,7 +1326,7 @@ def check_hello_result(msg): eq_(len(self.proto.ps.direct_updates), 0) eq_(len(self.proto.log.info.mock_calls), 1) args, kwargs = self.proto.log.info.call_args - eq_(args[0], "Ack") + eq_(kwargs.get('format') or args[0], "Ack") eq_(kwargs["router_key"], "simplepush") eq_(kwargs["message_source"], "direct") @@ -1358,7 +1358,7 @@ def test_ack_with_webpush_direct(self): eq_(self.proto.ps.direct_updates[chid], []) eq_(len(self.proto.log.info.mock_calls), 1) args, kwargs = self.proto.log.info.call_args - eq_(args[0], "Ack") + eq_(kwargs.get('format') or args[0], "Ack") eq_(kwargs["router_key"], "webpush") eq_(kwargs["message_source"], "direct") @@ -1383,7 +1383,7 @@ def test_ack_with_webpush_from_storage(self): assert mock_defer.addBoth.called eq_(len(self.proto.log.info.mock_calls), 1) args, kwargs = self.proto.log.info.call_args - eq_(args[0], "Ack") + eq_(kwargs.get('format') or args[0], "Ack") eq_(kwargs["router_key"], "webpush") eq_(kwargs["message_source"], "stored") diff --git a/autopush/utils.py b/autopush/utils.py index c85b8265..6ebc65eb 100644 --- a/autopush/utils.py +++ b/autopush/utils.py @@ -124,8 +124,11 @@ def write_error(self, code, **kwargs): """ self.set_status(code) if "exc_info" in kwargs: - self.log.failure(failure.Failure(*kwargs["exc_info"]), - **self._client_info) + format = kwargs.get("format", "Exception") + self.log.failure( + format=format, + failure=failure.Failure(*kwargs["exc_info"]), + **self._client_info) else: self.log.failure("Error in handler: %s" % code, **self._client_info) diff --git a/autopush/websocket.py b/autopush/websocket.py index da6b409e..080bc4e8 100644 --- a/autopush/websocket.py +++ b/autopush/websocket.py @@ -299,7 +299,7 @@ def base_tags(self): def log_failure(self, failure, **kwargs): """Log a twisted failure out through twisted's log.failure""" - self.log.failure("Unexpected error", failure, **kwargs) + self.log.failure(format="Unexpected error", failure=failure, **kwargs) @property def paused(self): @@ -1062,7 +1062,7 @@ def process_unregister(self, data): # Log out the unregister if it has a code in it if "code" in data: code = extract_code(data) - self.log.info("Unregister", channelID=chid, + self.log.info(format="Unregister", channelID=chid, uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, code=code) @@ -1123,7 +1123,7 @@ def ver_filter(update): if found: msg = found[0] size = len(msg.data) if msg.data else 0 - self.log.info("Ack", router_key="webpush", channelID=chid, + self.log.info(format="Ack", router_key="webpush", channelID=chid, message_id=version, message_source="direct", message_size=size, uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, code=code) @@ -1134,7 +1134,7 @@ def ver_filter(update): if found: msg = found[0] size = len(msg.data) if msg.data else 0 - self.log.info("Ack", router_key="webpush", channelID=chid, + self.log.info(format="Ack", router_key="webpush", channelID=chid, message_id=version, message_source="stored", message_size=size, uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, code=code) @@ -1167,12 +1167,13 @@ def _handle_simple_ack(self, chid, version, code): if chid in self.ps.direct_updates and \ self.ps.direct_updates[chid] <= version: del self.ps.direct_updates[chid] - self.log.info("Ack", router_key="simplepush", channelID=chid, - message_id=version, message_source="direct", + self.log.info(format="Ack", router_key="simplepush", + channelID=chid, message_id=version, + message_source="direct", uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, code=code) return - self.log.info("Ack", router_key="simplepush", channelID=chid, + self.log.info(format="Ack", router_key="simplepush", channelID=chid, message_id=version, message_source="stored", uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, code=code) @@ -1210,7 +1211,7 @@ def process_nack(self, data): version, updateid = version.split(":") - self.log.info("Nack", uaid_hash=self.ps.uaid_hash, + self.log.info(format="Nack", uaid_hash=self.ps.uaid_hash, user_agent=self.ps.user_agent, message_id=version, code=code)