[Checkins] SVN: zc.zservertracelog/trunk/ merged changes from alex-extensions-2 branch (r91089-91907).
Alex Smith
asmith at zope.com
Thu Oct 9 15:25:45 EDT 2008
Log message for revision 91938:
merged changes from alex-extensions-2 branch (r91089-91907).
Changed:
U zc.zservertracelog/trunk/CHANGES.txt
U zc.zservertracelog/trunk/setup.py
U zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml
U zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py
U zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
-=-
Modified: zc.zservertracelog/trunk/CHANGES.txt
===================================================================
--- zc.zservertracelog/trunk/CHANGES.txt 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/CHANGES.txt 2008-10-09 19:25:45 UTC (rev 91938)
@@ -9,4 +9,9 @@
* added automated tests.
-* added hooks for tracelog extensions.
+* fixed bug where log entries could be split by messages containing newline
+ characters.
+
+* added request query strings to log.
+
+* added the tracelog to the WSGI environment.
Modified: zc.zservertracelog/trunk/setup.py
===================================================================
--- zc.zservertracelog/trunk/setup.py 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/setup.py 2008-10-09 19:25:45 UTC (rev 91938)
@@ -21,7 +21,7 @@
name = 'zc.zservertracelog'
setup(
name = name,
- version = '0.3',
+ version = '0.4',
author = 'Jim Fulton',
author_email = 'jim at zope.com',
description = 'Zope 3 tracelog implementation for zserver',
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2008-10-09 19:25:45 UTC (rev 91938)
@@ -15,7 +15,7 @@
>>> import sys
>>> stdout_handler = logging.StreamHandler(sys.stdout)
- >>> logger = logging.getLogger('zc.tracelog')
+ >>> logger = logging.getLogger('zc.zservertracelog')
>>> logger.setLevel(logging.INFO)
>>> logger.addHandler(stdout_handler)
@@ -120,153 +120,78 @@
>>> faux_app.app_hook = None
-Tracelog Extensions
-===================
+Log Messages Containing Line Breaks
+===================================
-Additional information can be written to the trace log through the use of
-extensions. Extensions can be registered as named-utilities for any of the
-trace points mentioned above.
+Messages to the tracelog that contain newline characters will not split a log
+entry into multiple lines.
- >>> import zc.zservertracelog.interfaces
- >>> import zope.component
- >>> import zope.interface
-
- >>> site_manager = zope.component.getSiteManager()
-
-Extensions implement one or more of the sub-interfaces of ``ITracer``. Here,
-we'll define a simple extension that just logs how many times it's been
-called.
-
- >>> class CountTracer(object):
+ >>> req2 = """\
+ ... GET /test-req2/%0Aohnoes/ HTTP/1.1
+ ... Host: www.example.com/linebreak
...
- ... count = 0
- ...
- ... def __call__(self, logger, trace_point):
- ... self.count += 1
- ... logger.log('count: %s' % self.count)
+ ... """
+ >>> invokeRequest(req2)
+ B 21598352 2008-09-12T11:40:27 GET /test-req2/\nohnoes/
+ I 21598352 2008-09-12T11:40:27 0
+ C 21598352 2008-09-12T11:40:27
+ A 21598352 2008-09-12T11:40:27 200 ?
+ E 21598352 2008-09-12T11:40:27
- >>> count_tracer = CountTracer()
- >>> site_manager.registerUtility(
- ... count_tracer,
- ... zc.zservertracelog.interfaces.ITraceRequestStart,
- ... 'example.Tracer')
-Extensions appear in the log with the *X* prefix immediately after any trace
-point they are registered for.
+Request Query Strings
+=====================
- >>> invokeRequest(req1)
- B 17954544 2008-09-05T09:47:00 GET /test-req1
- X 17954544 2008-09-05T09:47:00 example.Tracer count: 1
- I 17954544 2008-09-05T09:47:00 0
- C 17954544 2008-09-05T09:47:00
- A 17954544 2008-09-05T09:47:00 200 ?
- E 17954544 2008-09-05T09:47:00
+The tracelog preserves request query strings.
-Unnamed extension registrations are not allowed and will result in a
-`ValueError` if present during execution.
-
- >>> site_manager.registerUtility(
- ... count_tracer, zc.zservertracelog.interfaces.ITraceRequestStart)
-
- >>> invokeRequest(req1)
- Traceback (most recent call last):
+ >>> req3 = """\
+ ... GET /test-req3/?creature=unicorn HTTP/1.1
+ ... Host: www.example.com/query-string
...
- ValueError: Unnamed Tracelog Extension
+ ... """
-To fix the problem, we'll just remove the extension. Since extensions are
-just utilities, removing an extension is accomplished simply by unregistering
-it.
+ >>> invokeRequest(req3)
+ B 21598352 2008-09-12T11:40:27 GET /test-req3/?creature=unicorn
+ I 21598352 2008-09-12T11:40:27 0
+ C 21598352 2008-09-12T11:40:27
+ A 21598352 2008-09-12T11:40:27 200 ?
+ E 21598352 2008-09-12T11:40:27
- >>> site_manager.unregisterUtility(
- ... count_tracer, zc.zservertracelog.interfaces.ITraceRequestStart)
- True
+Empty query strings are also preserved.
- >>> invokeRequest(req1)
- B 21714736 2008-09-05T13:45:44 GET /test-req1
- X 23418928 2008-08-26T10:55:00 example.Tracer count: 3
- I 21714736 2008-09-05T13:45:44 0
- C 21714736 2008-09-05T13:45:44
- A 21714736 2008-09-05T13:45:44 200 ?
- E 21714736 2008-09-05T13:45:44
+ >>> req4 = """\
+ ... GET /test-req4/? HTTP/1.1
+ ... Host: www.example.com/empty-query-string
+ ...
+ ... """
-So far, we've only added extensions for the *Request Start* trace point, and
-adding extensions for other trace points is done in almost the exact same
-way. The only difference is the interface which an extension is registered
-for.
+ >>> invokeRequest(req4)
+ B 21598352 2008-09-12T11:40:27 GET /test-req4/?
+ I 21598352 2008-09-12T11:40:27 0
+ C 21598352 2008-09-12T11:40:27
+ A 21598352 2008-09-12T11:40:27 200 ?
+ E 21598352 2008-09-12T11:40:27
-Here, we'll register the tracer component in the previous examples for the
-other trace points.
- >>> site_manager.registerUtility(
- ... count_tracer,
- ... zc.zservertracelog.interfaces.ITraceInputAcquired,
- ... 'example.Tracer')
+Adding Additional Entries to the Trace Log
+==========================================
- >>> site_manager.registerUtility(
- ... count_tracer,
- ... zc.zservertracelog.interfaces.ITraceApplicationStart,
- ... 'example.Tracer')
+A tracelog object is added to the WSGI environment on each request. This
+object implements ``ITraceLog`` and provides applications a method to add
+custom entries to the log.
- >>> site_manager.registerUtility(
- ... count_tracer,
- ... zc.zservertracelog.interfaces.ITraceApplicationEnd,
- ... 'example.Tracer')
+Here is an example application that adds a custom entry to the tracelog.
- >>> site_manager.registerUtility(
- ... count_tracer,
- ... zc.zservertracelog.interfaces.ITraceRequestEnd,
- ... 'example.Tracer')
+ >>> def noisy_app(environ, start_response):
+ ... logger = environ['zc.zservertracelog.interfaces.ITraceLog']
+ ... logger.log('beep! beep!')
+ >>> faux_app.app_hook = noisy_app
-Now, that extension is fired at every trace point.
-
>>> invokeRequest(req1)
- B 21930320 2008-09-05T15:53:47 GET /test-req1
- X 21930320 2008-09-05T15:53:47 example.Tracer count: 4
- I 21930320 2008-09-05T15:53:47 0
- X 21930320 2008-09-05T15:53:47 example.Tracer count: 5
- C 21930320 2008-09-05T15:53:47
- X 21930320 2008-09-05T15:53:47 example.Tracer count: 6
- A 21930320 2008-09-05T15:53:47 200 ?
- X 21930320 2008-09-05T15:53:47 example.Tracer count: 7
- E 21930320 2008-09-05T15:53:47
- X 21930320 2008-09-05T15:53:47 example.Tracer count: 8
-
-
-Overriding Extensions
----------------------
-
-One extension can be overriden with another just by registering the new
-extension with the same name.
-
-Let's add a new extension to demonstrate this.
-
- >>> class StreetLightTracer(object):
- ...
- ... light = 0
- ... colors = ['green', 'yellow', 'red']
- ...
- ... def __call__(self, logger, trace_point):
- ... self.light = self.light + 1 % 3
- ... logger.log('color: %s' % self.colors[self.light])
-
- >>> street_light_tracer = StreetLightTracer()
-
- >>> site_manager.registerUtility(
- ... street_light_tracer,
- ... zc.zservertracelog.interfaces.ITraceRequestStart,
- ... 'example.Tracer')
-
-Now, we see output from the new extension.
-
- >>> invokeRequest(req1)
- B 23418928 2008-08-26T10:55:00 GET /test-req1
- X 23418928 2008-08-26T10:55:00 example.Tracer color: yellow
- I 23418928 2008-08-26T10:55:00 0
- X 23418928 2008-08-26T10:55:00 example.Tracer count: 9
- C 23418928 2008-08-26T10:55:00
- X 23418928 2008-08-26T10:55:00 example.Tracer count: 10
- A 23418928 2008-08-26T10:55:00 200 ?
- X 23418928 2008-08-26T10:55:00 example.Tracer count: 11
- E 23418928 2008-08-26T10:55:00
- X 23418928 2008-08-26T10:55:00 example.Tracer count: 12
+ B 21569456 2008-09-12T15:51:05 GET /test-req1
+ I 21569456 2008-09-12T15:51:05 0
+ C 21569456 2008-09-12T15:51:05
+ X 21569456 2008-09-12T15:51:05 beep! beep!
+ A 21569456 2008-09-12T15:51:05 200 ?
+ E 21569456 2008-09-12T15:51:05
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml 2008-10-09 19:25:45 UTC (rev 91938)
@@ -1,3 +1,4 @@
+<?xml version="1.0" encoding="utf-8"?>
<configure xmlns="http://namespaces.zope.org/zope">
<utility
@@ -12,6 +13,8 @@
provides="zope.app.server.servertype.IServerType"
/>
+ <adapter factory="zc.zservertracelog.tracelog.get" />
+
<subscriber handler=".tracelog.started" />
</configure>
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py 2008-10-09 19:25:45 UTC (rev 91938)
@@ -19,34 +19,7 @@
class ITraceLog(zope.interface.Interface):
- """Logs records from writers."""
+ """Writes messages to the trace log."""
- def log(msg=None, timestamp=None):
+ def log(msg=None):
"""Write a message to the trace log."""
-
-
-class ITracer(zope.interface.Interface):
- """Enters trace points."""
-
- def __call__(logger, trace_point):
- """Record an entry in the trace log."""
-
-
-class ITraceRequestStart(ITracer):
- """Enters the *Request Start* trace point."""
-
-
-class ITraceInputAcquired(ITracer):
- """Enters the *Request Input Acquired* trace point."""
-
-
-class ITraceApplicationStart(ITracer):
- """Enters the *Application Start* trace point."""
-
-
-class ITraceApplicationEnd(ITracer):
- """Enters the *Application End* trace point."""
-
-
-class ITraceRequestEnd(ITracer):
- """Enters the *Request End* trace point."""
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2008-10-09 19:15:08 UTC (rev 91937)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2008-10-09 19:25:45 UTC (rev 91938)
@@ -26,70 +26,40 @@
import zope.server.http.httprequestparser
import zope.server.http.httpserverchannel
+tracelog = logging.getLogger('zc.zservertracelog')
-trace_points = {
- 'B': zc.zservertracelog.interfaces.ITraceRequestStart,
- 'I': zc.zservertracelog.interfaces.ITraceInputAcquired,
- 'C': zc.zservertracelog.interfaces.ITraceApplicationStart,
- 'A': zc.zservertracelog.interfaces.ITraceApplicationEnd,
- 'E': zc.zservertracelog.interfaces.ITraceRequestEnd,
- }
+def _format_datetime(dt):
+ return dt.replace(microsecond=0).isoformat()
-tracelog = logging.getLogger('zc.tracelog')
+def _log(channel_id, trace_code='X', msg=None, timestamp=None):
+ if timestamp is None:
+ timestamp = datetime.datetime.now()
-def _format_datetime(dt):
- return dt.replace(microsecond=0).isoformat()
+ entry = '%s %s %s' % (trace_code, channel_id, _format_datetime(timestamp))
+ if msg:
+ entry += ' %s' % repr(msg)[1:-1]
-def _log(logger, trace_code, msg=None, timestamp=None):
- logger.trace_code = trace_code
- logger.extension_id = None
- logger.log(msg, timestamp)
- _run_trace_extensions(trace_points[trace_code], logger)
+ tracelog.info(entry)
-def _run_trace_extensions(trace_point, logger):
- logger.trace_code = 'X'
- tracers = zope.component.getUtilitiesFor(trace_point)
- for tname, tracer in tracers:
- logger.extension_id = tname
- tracer(logger, trace_point)
- logger.extension_id = None
+ at zope.component.adapter(zope.publisher.interfaces.IRequest)
+ at zope.interface.implementer(zc.zservertracelog.interfaces.ITraceLog)
+def get(request):
+ return request['zc.zservertracelog.interfaces.ITraceLog']
class TraceLog(object):
zope.interface.implements(zc.zservertracelog.interfaces.ITraceLog)
- extension_id = None
- trace_code = None
+ def __init__(self, channel_id):
+ self.channel_id = channel_id
- def __init__(self, channel):
- self.channel_id = id(channel)
+ def log(self, msg=None):
+ _log(self.channel_id, 'X', msg)
- def log(self, msg=None, timestamp=None):
- if timestamp is None:
- timestamp = datetime.datetime.now()
-
- if not self.trace_code:
- self.trace_code = 'X'
-
- if self.trace_code == 'X' and not self.extension_id:
- raise ValueError('Unnamed Tracelog Extension')
-
- entry = '%s %s %s' % (
- self.trace_code, self.channel_id, _format_datetime(timestamp))
-
- if self.extension_id:
- entry += ' %s' % self.extension_id
-
- if msg:
- entry += ' %s' % msg
-
- tracelog.info(entry)
-
-
class Parser(zope.server.http.httprequestparser.HTTPRequestParser):
def __init__(self, x):
@@ -101,9 +71,16 @@
parser_class = Parser
def handle_request(self, parser):
- logger = TraceLog(self)
- _log(logger, 'B', '%s %s' % (parser.command, parser.path), parser.__B)
- _log(logger, 'I', str(parser.content_length))
+ full_path = parser.path
+ if parser.query:
+ full_path += '?%s' % parser.query
+ elif parser.query is not None:
+ full_path += '?'
+
+ cid = id(self)
+ _log(cid, 'B', '%s %s' % (parser.command, full_path), parser.__B)
+ _log(cid, 'I', str(parser.content_length))
+
zope.server.http.httpserverchannel.HTTPServerChannel.handle_request(
self, parser)
@@ -118,10 +95,11 @@
def executeRequest(self, task):
"""Overrides HTTPServer.executeRequest()."""
- logger = TraceLog(task.channel)
- _log(logger, 'C')
+ cid = id(task.channel)
+ _log(cid, 'C')
env = task.getCGIEnvironment()
env['wsgi.input'] = task.request_data.getBodyStream()
+ env['zc.zservertracelog.interfaces.ITraceLog'] = TraceLog(cid)
def start_response(status, headers):
# Prepare the headers for output
@@ -136,8 +114,8 @@
try:
response = self.application(env, start_response)
except Exception, v:
- _log(logger, 'A', 'Error: %s' % v)
- _log(logger, 'E')
+ _log(cid, 'A', 'Error: %s' % v)
+ _log(cid, 'E')
raise
else:
accumulated_headers = getattr(task, 'accumulated_headers') or ()
@@ -149,15 +127,15 @@
else:
length = '?'
- _log(logger, 'A', '%s %s' % (getattr(task, 'status', '?'), length))
+ _log(cid, 'A', '%s %s' % (getattr(task, 'status', '?'), length))
try:
task.write(response)
except Exception, v:
- _log(logger, 'E', 'Error: %s' % v)
+ _log(cid, 'E', 'Error: %s' % v)
raise
else:
- _log(logger, 'E')
+ _log(cid, 'E')
http = servertype.ServerType(
More information about the Checkins
mailing list