[Repoze-checkins] r1153 - in repoze.debug/trunk: . repoze/debug repoze/debug/tests
Chris McDonough
chrism at agendaless.com
Fri Jun 27 22:16:22 EDT 2008
Author: Chris McDonough <chrism at agendaless.com>
Date: Fri Jun 27 22:16:22 2008
New Revision: 1153
Log:
- Deal with responses via a generator; don't unwind response bodies
into memory.
- Default max_bodysize is now 3K rather than the entire response
body.
- User interface; keep entries around to show in GUI.
Modified:
repoze.debug/trunk/CHANGES.txt
repoze.debug/trunk/repoze/debug/responselogger.py
repoze.debug/trunk/repoze/debug/tests/test_responselogger.py
repoze.debug/trunk/repoze/debug/ui.py
Modified: repoze.debug/trunk/CHANGES.txt
==============================================================================
--- repoze.debug/trunk/CHANGES.txt (original)
+++ repoze.debug/trunk/CHANGES.txt Fri Jun 27 22:16:22 2008
@@ -1,8 +1,16 @@
Next release
- - Make debug id monotonically increase from zero instead of using a
+ - Make debug request id reflect approximate UNIX time rather than a
random debug id.
+ - Deal with responses via a generator; don't unwind response bodies
+ into memory.
+
+ - Default max_bodysize is now 3K rather than the entire response
+ body.
+
+ - User interface; keep entries around to show in GUI.
+
0.4 (2008/06/25)
- Add pdbpm middleware for dropping into the post-mortem debugger
Modified: repoze.debug/trunk/repoze/debug/responselogger.py
==============================================================================
--- repoze.debug/trunk/repoze/debug/responselogger.py (original)
+++ repoze.debug/trunk/repoze/debug/responselogger.py Fri Jun 27 22:16:22 2008
@@ -1,20 +1,36 @@
+import itertools
import time
import threading
from paste.exceptions.errormiddleware import Supplement
+from paste.response import header_value
from repoze.debug.ui import is_gui_url
from repoze.debug.ui import DebugGui
class ResponseLoggingMiddleware:
- def __init__(self, app, max_bodylen, logger):
+ def __init__(self, app, max_bodylen, logger, keep_around):
self.application = app
self.max_bodylen = max_bodylen
self.logger = logger
+ self.keep_around = keep_around
+ self.entries = []
+ self.lock = threading.Lock()
def __call__(self, environ, start_response):
if is_gui_url(environ):
- gui = DebugGui(self)
- return gui(environ, start_response)
+ self.lock.acquire()
+ try:
+ gui = DebugGui(self)
+ return gui(environ, start_response)
+ finally:
+ self.lock.release()
+
+ self.lock.acquire()
+ try:
+ if len(self.entries) > self.keep_around:
+ self.entries.pop(0)
+ finally:
+ self.lock.release()
now = time.time()
request_id = get_request_id(now)
@@ -26,98 +42,118 @@
self.log_request(environ)
catch_response = []
- body = []
+ written = []
def replace_start_response(status, headers, exc_info=None):
catch_response.append([status, headers])
start_response(status, headers, exc_info)
- return body.append
+ return written.append
app_iter = self.application(environ, replace_start_response)
+ body = itertools.chain(written, app_iter)
- try:
- body.extend(app_iter)
- finally:
- if hasattr(app_iter, 'close'):
- app_iter.close()
-
- body = ''.join(body)
if catch_response:
status, headers = catch_response[0]
else:
status = '500 Start Response Not Called'
headers = []
- self.log_response(environ, status, headers, body)
+ body = self.log_response(environ, status, headers, body)
- return [body]
+ if hasattr(app_iter, 'close'):
+ app_iter.close()
- def log_request(self, environ):
+ return body
+
+ def _add_request_data(self, environ):
supplement = Supplement(self, environ)
request_data = supplement.extraData()
- debug = environ['repoze.debug']
- request_id = debug['id']
+ entry = environ['repoze.debug']
+ entry['url'] = supplement.source_url
+ entry['cgi_variables'] = []
+ entry['wsgi_variables'] = []
+ for k, v in sorted(request_data[('extra', 'CGI Variables')].items()):
+ entry['cgi_variables'].append((k, v))
+ for k, v in sorted(request_data[('extra', 'WSGI Variables')].items()):
+ if not 'repoze.debug' in k:
+ entry['wsgi_variables'].append((k, v))
+ return entry
+
+ def log_request(self, environ):
+ entry = self._add_request_data(environ)
+ request_id = entry['id']
out = []
t = time.ctime()
out.append('--- REQUEST %s at %s ---' % (request_id, t))
- url = supplement.source_url
- debug['url'] = url
- out.append('URL: %s' % url)
+ out.append('URL: %s' % entry['url'])
out.append('CGI Variables')
- items = request_data[('extra', 'CGI Variables')].items()
- items.sort()
- for k, v in items:
+ for k, v in entry['cgi_variables']:
out.append(' %s: %s' % (k, v))
out.append('WSGI Variables')
- items = request_data[('extra', 'WSGI Variables')].items()
- for k, v in items:
+ for k, v in entry['wsgi_variables']:
out.append(' %s: %s' % (k, v))
out.append('--- end REQUEST %s ---' % request_id)
self.logger.info('\n'.join(out))
+ def _add_response_data(self, environ, status, headers):
+ entry = environ.get('repoze.debug', {})
+ end = time.time()
+ entry['end'] = end
+ cl = header_value(headers, 'content-length')
+ entry['response_headers'] = list(headers)
+ try:
+ cl = int(cl)
+ except (TypeError, ValueError):
+ cl = None
+ entry['content-length'] = cl
+ entry['status'] = status
+ method = environ.get('REQUEST_METHOD', 'GET')
+ entry['title'] = '%s %s' % (method, entry.get('url', '??'))
+ return entry
+
def log_response(self, environ, status, headers, body):
- debug = environ.get('repoze.debug', {})
- request_id = debug.get('id')
+ entry = self._add_response_data(environ, status, headers)
+ request_id = entry.get('id')
out = []
- t = time.ctime()
- end = time.time()
- start = debug.get('begin')
- if start:
+ start, end = entry.get('begin'), entry.get('end')
+ if start and end:
duration = end - start
else:
duration = '??'
+ t = time.asctime(time.localtime(end))
out.append('--- RESPONSE %s at %s (%0.4f seconds) ---' % (
request_id, t, duration))
- url = debug.get('url', '??')
- out.append('URL: %s' % url)
+ out.append('URL: %s' % entry.get('url', '??'))
out.append('Status: %s' % status)
out.append('Response Headers')
- cl = None
- for header in headers:
- k, v = header
- if k.lower() == 'content-length':
- try:
- cl = int(v)
- except (TypeError, ValueError):
- cl = None
+ for k, v in entry['response_headers']:
out.append(' %s: %s' % (k, v))
- bodylen = len(body)
+ bodyout = ''
+ bodylen = 0
+ remaining = None
+ for chunk in body:
+ if self.max_bodylen:
+ remaining = max(0, self.max_bodylen - len(bodyout))
+ bodyout += chunk[:remaining]
+ bodylen += len(chunk)
+ yield chunk
+ if bodylen > self.max_bodylen:
+ bodyout += ' ... (truncated)'
+ out.append('Body:\n' + bodyout)
out.append('Bodylen: %s' % bodylen)
+ cl = entry['content-length']
if cl is not None:
if bodylen != cl:
out.append(
'WARNING-1: bodylen (%s) != Content-Length '
'header value (%s)' % (bodylen, cl))
- out.append('Body:')
- out.append('')
- bodyout = body
- if self.max_bodylen:
- bodyout = body[:self.max_bodylen]
- if len(body) > self.max_bodylen:
- bodyout += ' ... (truncated)'
- out.append(bodyout)
out.append('--- end RESPONSE %s ---' % request_id)
self.logger.info('\n'.join(out))
+ self.lock.acquire()
+ try:
+ self.entries.append(entry)
+ finally:
+ self.lock.release()
class SuffixMultiplier:
# d is a dictionary of suffixes to integer multipliers. If no suffixes
@@ -177,14 +213,16 @@
def make_middleware(app,
global_conf,
filename,
- max_bodylen='0KB', # all
+ max_bodylen='3KB',
max_logsize='100MB',
backup_count='10',
+ keep_around='100',
):
""" Paste filter-app converter """
backup_count = int(backup_count)
max_bytes = byte_size(max_logsize)
max_bodylen = byte_size(max_bodylen)
+ keep_around = int(keep_around)
from logging import Logger
from logging.handlers import RotatingFileHandler
@@ -193,4 +231,4 @@
backupCount=backup_count)
logger = Logger('repoze.debug.responselogger')
logger.handlers = [handler]
- return ResponseLoggingMiddleware(app, max_bodylen, logger)
+ return ResponseLoggingMiddleware(app, max_bodylen, logger, keep_around)
Modified: repoze.debug/trunk/repoze/debug/tests/test_responselogger.py
==============================================================================
--- repoze.debug/trunk/repoze/debug/tests/test_responselogger.py (original)
+++ repoze.debug/trunk/repoze/debug/tests/test_responselogger.py Fri Jun 27 22:16:22 2008
@@ -25,11 +25,11 @@
body = ['thebody']
app = DummyApp(body, '200 OK', [('HeaderKey', 'headervalue')])
logger = FakeLogger()
- mw = self._makeOne(app, 0, logger)
+ mw = self._makeOne(app, 0, logger, 10)
environ = self._makeEnviron()
start_response = FakeStartResponse()
app_iter = mw(environ, start_response)
- self.assertEqual(''.join(app_iter), 'thebody')
+ self.assertEqual(''.join(list(app_iter)), 'thebody')
self.assertEqual(len(logger.logged), 2)
self.assertEqual(start_response.status, '200 OK')
self.assertEqual(len(start_response.headers), 1)
@@ -41,7 +41,7 @@
body = ['thebody']
app = DummyApp(body, '200 OK', [('HeaderKey', 'headervalue')])
logger = FakeLogger()
- mw = self._makeOne(app, 1, logger)
+ mw = self._makeOne(app, 1, logger, 10)
environ = self._makeEnviron()
start_response = FakeStartResponse()
app_iter = mw(environ, start_response)
@@ -53,7 +53,7 @@
body = ['thebody']
app = DummyApp(body, '200 OK', [('Content-Length', '1')])
logger = FakeLogger()
- mw = self._makeOne(app, 1, logger)
+ mw = self._makeOne(app, 1, logger, 10)
environ = self._makeEnviron()
start_response = FakeStartResponse()
app_iter = mw(environ, start_response)
@@ -65,7 +65,7 @@
body = ['thebody']
app = DummyApp(body, '200 OK', [('Content-Length', '1')])
logger = FakeLogger()
- mw = self._makeOne(app, 1, logger)
+ mw = self._makeOne(app, 1, logger, 10)
environ = self._makeEnviron()
start_response = FakeStartResponse()
app_iter = mw(environ, start_response)
@@ -73,6 +73,28 @@
self.assertEqual(len(logger.logged), 2)
self.failUnless('URL: http://localhost' in logger.logged[1])
+ def test_entry_created(self):
+ body = ['thebody']
+ app = DummyApp(body, '200 OK', [('Content-Length', '1')])
+ logger = FakeLogger()
+ mw = self._makeOne(app, 1, logger, 10)
+ environ = self._makeEnviron()
+ start_response = FakeStartResponse()
+ app_iter = mw(environ, start_response)
+ self.assertEqual(''.join(app_iter), 'thebody')
+ self.assertEqual(len(mw.entries), 1)
+ entry = mw.entries[0]
+ self.assertEqual(entry['status'], '200 OK')
+ self.failUnless(isinstance(entry['begin'], float))
+ self.failUnless(isinstance(entry['end'], float))
+ self.assertEqual(entry['response_headers'],
+ [('Content-Length', '1')])
+ self.assertEqual(entry['url'], 'http://localhost')
+ self.assertEqual(entry['content-length'], 1)
+ self.assertEqual(len(entry['cgi_variables']), 2)
+ self.assertEqual(len(entry['wsgi_variables']), 2)
+ self.failUnless(isinstance(entry['id'], float))
+
class TestMakeResponseLoggingMiddleware(unittest.TestCase):
def _getFUT(self):
from repoze.debug.responselogger import make_middleware
@@ -86,7 +108,8 @@
fn = tempfile.mktemp()
mw = f(app, global_conf, fn)
self.assertEqual(len(mw.logger.handlers), 1)
- self.assertEqual(mw.max_bodylen, 0)
+ self.assertEqual(mw.max_bodylen, 3072)
+ self.assertEqual(mw.keep_around, 100)
def test_make_middleware_nondefaults(self):
f = self._getFUT()
@@ -94,7 +117,7 @@
global_conf = {}
import tempfile
fn = tempfile.mktemp()
- mw = f(app, global_conf, fn, '0', '0')
+ mw = f(app, global_conf, fn, '0', '0', '0', '0')
self.assertEqual(len(mw.logger.handlers), 1)
class FakeStartResponse:
Modified: repoze.debug/trunk/repoze/debug/ui.py
==============================================================================
--- repoze.debug/trunk/repoze/debug/ui.py (original)
+++ repoze.debug/trunk/repoze/debug/ui.py Fri Jun 27 22:16:22 2008
@@ -19,22 +19,17 @@
return type or 'application/octet-stream'
-class FakeLogger(object):
-
- def getEntries(self):
-
- data = [
- {'id': '20323', 'title': 'My Entry'},
- {'id': '32736', 'title': 'Second Entry'},
- ]
-
- return data
+class FakeMiddleware(object):
+ entries = [
+ {'id': '20323', 'title': 'My Entry'},
+ {'id': '32736', 'title': 'Second Entry'},
+ ]
class DebugGui(object):
- def __init__(self, logger):
- self.logger = logger
+ def __init__(self, middleware):
+ self.middleware = middleware
self.static_dir = os.path.join(_HERE, 'static')
def __call__(self, environ, start_response):
@@ -69,10 +64,9 @@
return res
def getFeed(self, req):
- """Get XML representing information in the logger"""
+ """Get XML representing information in the middleware"""
- logger = FakeLogger()
- entries = logger.getEntries()
+ entries = self.middleware.entries
feedfmt = """<?xml version="1.0" encoding="utf-8"?>
<feed xmlns="http://www.w3.org/2005/Atom">
More information about the Repoze-checkins
mailing list