Failure logging is incorrect

[bbangert]

Logging errors is broken as instances are still sneaking in, better checks need to be done, and the format attempt itself should be in a try/except, with errors sentry reported.

[jrconlin]

@bbangert could you add an example of a bad log entry? It'd be useful in the future to check for regression or if we see something similar.

[bbangert]

Sure, this is a sample:

May 05 16:53:21 ip-172-31-39-23 python[11560]: Unable to format event {'uaid_hash': 'asdfasdfasdfasdfasdfsd', 'log_namespace': 'autopush.endpoint.EndpointHandler', 'log_level': <LogLevel=critical>, 'message_ttl': '200', 'log_logger': <Logger 'autopush.endpoint.EndpointHandler'>, 'channelID': 'asdfasdfasdfasdfasdf', 'log_source': <autopush.endpoint.EndpointHandler object at 0x38f99c50>, 'log_format': <twisted.python.failure.Failure exceptions.KeyError: u'prod.autopush.message_2016_2'>, 'message_size': 489, 'authorization': '', 'router_key': u'webpush', 'request_id': 'fa877aa4-1702-4d13-ba4d-5d2ab313b165', 'log_time': 1462467201.143596, 'remote_ip': '184.173.141.4', 'message_id':'asdfasdfasdfasdfasdfasdfasdfsdaf-asdfasdfasdfasdfsdafasdfasdf=', 'log_failure': <twisted.python.failure.Failure exceptions.KeyError: u'prod.autopush.message_2016_2'>, 'user_agent': ''}: Log format must be unicode or bytes, not <twisted.python.failure.Failure exceptions.KeyError: u'prod.autopush.message_2016_2'> 

I replaced some ID's there of course. In this case log_format seems to have gotten a failure instance which can't be formatted of course. This definitely should've resulted in a Sentry call as well, but no Sentry call, I'm not sure its being called properly actually.

Per https://docs.getsentry.com/hosted/clients/python/api/, it appears captureException takes a 'message' argument, and then the exc_info. We are not passing a message, and only passing the exc_info tuple, so that might explain the problem.

We should have a method somewhere we can hit when in stage, that trigger an exception on purpose for Sentry reporting so we can verify it works.

[bbangert]

I should note, since the problematic fields here are not included in our custom JSON, my guess is that the formatEvent call on line 127 is failing, thus this error. It should be wrapped in a try/except and the message can be set to, 'unable to format event', and include a repr of the event instead.

[bbangert]

We are apparently not logging failures correctly. log.failure takes a message as the first arg, not a failure instance. The failure instance should be passed as failure=, per the docs: https://twistedmatrix.com/documents/16.1.1/api/twisted.logger.Logger.html#failure