← Back to team overview

launchpad-reviewers team mailing list archive

[Merge] lp:~spiv/launchpad/loggerhead-logging into lp:launchpad

 

Andrew Bennetts has proposed merging lp:~spiv/launchpad/loggerhead-logging into lp:launchpad.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)


This is a small change to start-loggerhead.py to add explicit logging for the completion of a request (in addition to the logging of the start of processing a request).  It logs the time taken between the request start and finish (even when requests trigger errors), and summarises the error if there is an error.

The main goal of this patch is to make it easier to gather stats about how long requests take.
-- 
https://code.launchpad.net/~spiv/launchpad/loggerhead-logging/+merge/29962
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~spiv/launchpad/loggerhead-logging into lp:launchpad.
=== modified file 'scripts/start-loggerhead.py'
--- scripts/start-loggerhead.py	2010-06-08 15:43:13 +0000
+++ scripts/start-loggerhead.py	2010-07-15 09:31:00 +0000
@@ -8,12 +8,15 @@
 import logging
 import os
 import sys
+import time
+import traceback
 
 from paste import httpserver
 from paste.deploy.config import PrefixMiddleware
 from paste.httpexceptions import HTTPExceptionHandler
 from paste.request import construct_url
 from paste.translogger import TransLogger
+from paste.wsgilib import catch_errors
 
 from canonical.config import config
 import lp.codehosting
@@ -129,13 +132,22 @@
 app = RootApp(SESSION_VAR)
 app = HTTPExceptionHandler(app)
 app = SessionHandler(app, SESSION_VAR, secret)
-def log_on_request_start(app):
+def log_request_start_and_stop(app):
     def wrapped(environ, start_response):
         log = logging.getLogger('loggerhead')
-        log.info("Starting to process %s", construct_url(environ))
-        return app(environ, start_response)
+        url = construct_url(environ)
+        log.info("Starting to process %s", url)
+        start_time = time.time()
+        def request_done_ok():
+            log.info("Processed ok %s [%0.3f seconds]", url, time.time() -
+                    start_time)
+        def request_done_err(exc_info):
+            log.info("Processed err %s [%0.3f seconds]: %s", url, time.time() -
+                    start_time, traceback.format_exception_only(*exc_info[:2]))
+        return catch_errors(app, environ, start_response, request_done_err,
+                request_done_ok)
     return wrapped
-app = log_on_request_start(app)
+app = log_request_start_and_stop(app)
 app = PrefixMiddleware(app)
 app = TransLogger(app)
 app = threadpool_debug(app)