859861 - improve readability of balrog request logs

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[[e-mail] (:bhearsum)]

Balrog application logs don't buffer at all right now, so we end up with output from multiple requests all interleaved. Eg:
2013-04-09 08:12:18,240 - SingleLocaleView.put#47: processing PUT request to /releases/Firefox-mozilla-aurora-nightly-20130409004013/builds/Linux_x86-gcc3/ms
2013-04-09 08:12:18,254 - SingleLocaleView.put#47: processing PUT request to /releases/Firefox-mozilla-aurora-nightly-20130409004013/builds/Linux_x86-gcc3/pt-BR
2013-04-09 08:12:18,296 - mozilla_buildtools.retry.retry#26: retry: Calling <bound method Releases.getReleases of <auslib.db.Releases object at 0xb3bd65ec>> with args: (), kwargs: {'transaction': <auslib.db.AUSTransaction object at 0xb283bb0c>, 'name': u'Firefox-mozilla-aurora-nightly-20130409004013'}, attempt #1
2013-04-09 08:12:18,297 - Releases.getReleases#732: Looking for releases with:
2013-04-09 08:12:18,298 - Releases.getReleases#733: name: Firefox-mozilla-aurora-nightly-20130409004013
2013-04-09 08:12:18,299 - Releases.getReleases#734: product: None
2013-04-09 08:12:18,299 - Releases.getReleases#735: version: None
2013-04-09 08:12:18,302 - AUSTransaction.execute#89: Attempting to execute SELECT releases.name, releases.product, releases.version, releases.data, releases.data_version
FROM releases
WHERE releases.name = %s
2013-04-09 08:12:18,313 - mozilla_buildtools.retry.retry#26: retry: Calling <bound method Releases.getReleases of <auslib.db.Releases object at 0xb3bda5ec>> with args: (), kwargs: {'transaction': <auslib.db.AUSTransaction object at 0xb2813d8c>, 'name': u'Firefox-mozilla-aurora-nightly-20130409004013'}, attempt #1
2013-04-09 08:12:18,314 - Releases.getReleases#732: Looking for releases with:
2013-04-09 08:12:18,315 - Releases.getReleases#733: name: Firefox-mozilla-aurora-nightly-20130409004013
2013-04-09 08:12:18,316 - Releases.getReleases#734: product: None
2013-04-09 08:12:18,316 - Releases.getReleases#735: version: None
2013-04-09 08:12:18,320 - AUSTransaction.execute#89: Attempting to execute SELECT releases.name, releases.product, releases.version, releases.data, releases.data_version
FROM releases
WHERE releases.name = %s


This makes it very hard to debug problems like 851585, where we want to analyze a request as a whole. Two ideas about how to fix this:
1) Add PID and id(request) to log messages, this should let us use grep to isolate messages from individual requests.
2) Buffer log messages until a request is complete, then print out the message. Not 100% sure if this will work given that we have multiple threads + processes.

Comment 1

[[e-mail] (:bhearsum)]

Attachment: add pid and request id to log messages

This patch adds the PID and "request id" (which is Python ID of the Request object) to all log messages. Here's a few sample messages through admin.wsgi:
2013-04-09 15:42:05,931 - PID: 20670 - Request: 140450020122128 - mozilla_buildtools.retry.retry#26: retry: Calling <bound method Releases.getReleaseNames of <auslib.db.Releases object at 0x7fbd118caad0>> with args: (), kwargs: {}, attempt #1
2013-04-09 15:42:05,934 - PID: 20670 - Request: 140450020122128 - RulesPageView.get#29: {u'comment': None, u'product': None, u'throttle': 100L, u'data_version': 1L, u'buildID': None, u'mapping': 'Firefox-mozilla-central-nightly-latest', u'priority': 100L, u'locale': None, u'version': None, u'headerArchitecture': None, u'update_type': 'minor', u'buildTarget': None, u'distribution': None, u'osVersion': None, u'rule_id': 1L, u'channel': None, u'distVersion': None}
2013-04-09 15:42:06,937 - PID: 16242 - Request: 140450021299728 - mozilla_buildtools.retry.retry#26: retry: Calling <bound method Releases.getReleaseNames of <auslib.db.Releases object at 0x7fbd118caad0>> with args: (), kwargs: {}, attempt #1
2013-04-09 15:42:06,940 - PID: 16242 - Request: 140450021299728 - RulesPageView.get#29: {u'comment': None, u'product': None, u'throttle': 100L, u'data_version': 1L, u'buildID': None, u'mapping': 'Firefox-mozilla-central-nightly-latest', u'priority': 100L, u'locale': None, u'version': None, u'headerArchitecture': None, u'update_type': 'minor', u'buildTarget': None, u'distribution': None, u'osVersion': None, u'rule_id': 1L, u'channel': None, u'distVersion': None}
2013-04-09 15:42:09,340 - PID: 20670 - Request: 140450020254480 - mozilla_buildtools.retry.retry#26: retry: Calling <bound method Releases.getReleaseNames of <auslib.db.Releases object at 0x7fbd118caad0>> with args: (), kwargs: {}, attempt #1
2013-04-09 15:42:09,341 - PID: 20670 - Request: 140450020254480 - RulesPageView.get#29: {u'comment': None, u'product': None, u'throttle': 100L, u'data_version': 1L, u'buildID': None, u'mapping': 'Firefox-mozilla-central-nightly-latest', u'priority': 100L, u'locale': None, u'version': None, u'headerArchitecture': None, u'update_type': 'minor', u'buildTarget': None, u'distribution': None, u'osVersion': None, u'rule_id': 1L, u'channel': None, u'distVersion': None}

I had to do a little bit of import re-arraging to make sure that logging is fully set-up when other modules are imported. Without that things like retry() grabbed their Logger before the setLoggerClass call which resulted in Exceptions because requestid wasn't defined.

With this patch you can look at a log and grep for the PID+Request ID to get the log messages you actually care about.

Comment 2

[[github robot]]

Commit pushed to master at https://github.com/mozilla/balrog

https://github.com/mozilla/balrog/commit/54c252134da1eb2b0162346a950d87adf84f4bea
bug 859861: improve readability of balrog request logs. r=nthomas

Comment 3

[[e-mail] (:bhearsum)]

I see this working in dev:
2013-04-10 11:02:34,535 - PID: 24249 - Request: None - raven.base.Client.__init__#146: Configuring Raven for host: threaded+https://9f5ea3def9514645a7dcef8353cc7ddd:[e-mail]:/12
2013-04-10 11:02:34,539 - PID: 24249 - Request: 3014987436 - IndexPageView.get#15: Balrog version is: 0.1.5
2013-04-10 11:02:37,860 - PID: 24251 - Request: None - raven.base.Client.__init__#146: Configuring Raven for host: threaded+https://9f5ea3def9514645a7dcef8353cc7ddd:[e-mail]:/12
2013-04-10 11:02:42,847 - PID: 24250 - Request: None - raven.base.Client.__init__#146: Configuring Raven for host: threaded+https://9f5ea3def9514645a7dcef8353cc7ddd:[e-mail]:/12
2013-04-10 11:02:45,659 - PID: 24252 - Request: None - raven.base.Client.__init__#146: Configuring Raven for host: threaded+https://9f5ea3def9514645a7dcef8353cc7ddd:[e-mail]:/12