1187735 - A lot of KeyError: 'requestid' in balrog logs

Status: RESOLVED FIXED

(Release Engineering Graveyard :: Applications: Balrog (backend), defect, P3)

Description

[Rail Aliiev [:rail]]

I was poking around some balrog HTTP 500 errors and saw these errors:

[Sun Jul 26 13:09:16 2015] [error] KeyError: 'requestid'
[Sun Jul 26 13:09:19 2015] [error] Traceback (most recent call last):
[Sun Jul 26 13:09:19 2015] [error]   File "/usr/lib64/python2.6/logging/__init__.py", line 776, in emit
[Sun Jul 26 13:09:19 2015] [error]     msg = self.format(record)
[Sun Jul 26 13:09:19 2015] [error]   File "/usr/lib64/python2.6/logging/__init__.py", line 654, in format
[Sun Jul 26 13:09:19 2015] [error]     return fmt.format(record)
[Sun Jul 26 13:09:19 2015] [error]   File "/usr/lib64/python2.6/logging/__init__.py", line 439, in format
[Sun Jul 26 13:09:19 2015] [error]     s = self._fmt % record.__dict__

Comment 1

[Nick Thomas [:nthomas] (UTC+12)]

I could have sworn I'd filed this before but apparently not ... This has been around for sometime, particularly when working in Vagrant - there's something not quite right in the logging at https://github.com/mozilla/balrog/blob/master/auslib/log.py#L9. Either there's an error unrelated to a request, or it occurs before requestid is available.

Comment 2

[[e-mail] (:bhearsum)]

This is probably caused by the custom Logger code at https://github.com/mozilla/balrog/blob/master/auslib/log.py#L12. I think it's probably best just to kill this now, since our Exception logging is done with Sentry, which makes it trivial to associate log messages with requests.

Comment 3

[[e-mail] (:bhearsum)]

Thomas found a fix for this: https://github.com/mozilla/balrog/pull/219

Thank you for that!

Comment 4

[[e-mail] (:bhearsum)]

In production, thanks for fixing this Thomas!