[Checkins] SVN: zc.zservertracelog/trunk/ merged in changes from alex-tracelog-extensions branch (r90841-90950).
Alex Smith
asmith at zope.com
Mon Sep 8 11:37:22 EDT 2008
Log message for revision 90951:
merged in changes from alex-tracelog-extensions branch (r90841-90950).
Changed:
U zc.zservertracelog/trunk/CHANGES.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
A 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-09-08 15:13:26 UTC (rev 90950)
+++ zc.zservertracelog/trunk/CHANGES.txt 2008-09-08 15:37:21 UTC (rev 90951)
@@ -9,3 +9,4 @@
* added automated tests.
+* added hooks for tracelog extensions.
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2008-09-08 15:13:26 UTC (rev 90950)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2008-09-08 15:37:21 UTC (rev 90951)
@@ -114,3 +114,159 @@
C 21651664 2008-09-02T13:59:02
A 21651664 2008-09-02T13:59:02 200 ?
E 21651664 2008-09-02T13:59:02 Error: iteration over non-sequence
+
+Let's clean up before moving on.
+
+ >>> faux_app.app_hook = None
+
+
+Tracelog Extensions
+===================
+
+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.
+
+ >>> 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):
+ ...
+ ... count = 0
+ ...
+ ... def __call__(self, logger, trace_point):
+ ... self.count += 1
+ ... logger.log('count: %s' % self.count)
+
+
+ >>> 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.
+
+ >>> 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
+
+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):
+ ...
+ 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.
+
+ >>> site_manager.unregisterUtility(
+ ... count_tracer, zc.zservertracelog.interfaces.ITraceRequestStart)
+ True
+
+ >>> 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
+
+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.
+
+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')
+
+ >>> site_manager.registerUtility(
+ ... count_tracer,
+ ... zc.zservertracelog.interfaces.ITraceApplicationStart,
+ ... 'example.Tracer')
+
+ >>> site_manager.registerUtility(
+ ... count_tracer,
+ ... zc.zservertracelog.interfaces.ITraceApplicationEnd,
+ ... 'example.Tracer')
+
+ >>> site_manager.registerUtility(
+ ... count_tracer,
+ ... zc.zservertracelog.interfaces.ITraceRequestEnd,
+ ... 'example.Tracer')
+
+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
Copied: zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py (from rev 90950, zc.zservertracelog/branches/alex-tracelog-extensions/src/zc/zservertracelog/interfaces.py)
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py (rev 0)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/interfaces.py 2008-09-08 15:37:21 UTC (rev 90951)
@@ -0,0 +1,52 @@
+##############################################################################
+#
+# Copyright (c) 2008 Zope Corporation and Contributors.
+# All Rights Reserved.
+#
+# This software is subject to the provisions of the Zope Public License,
+# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
+# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
+# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
+# FOR A PARTICULAR PURPOSE.
+#
+##############################################################################
+"""tracelog interfaces
+"""
+__docformat__ = "reStructuredText"
+
+import zope.interface
+
+
+class ITraceLog(zope.interface.Interface):
+ """Logs records from writers."""
+
+ def log(msg=None, timestamp=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-09-08 15:13:26 UTC (rev 90950)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2008-09-08 15:37:21 UTC (rev 90951)
@@ -20,31 +20,90 @@
import datetime
import logging
import re
+import zc.zservertracelog.interfaces
import zope.app.appsetup.interfaces
import zope.component
import zope.server.http.httprequestparser
import zope.server.http.httpserverchannel
-logger = logging.getLogger('zc.tracelog')
+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 now():
- return datetime.datetime.now().replace(microsecond=0).isoformat()
+tracelog = logging.getLogger('zc.tracelog')
+
+def _format_datetime(dt):
+ return dt.replace(microsecond=0).isoformat()
+
+
+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)
+
+
+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
+
+
+class TraceLog(object):
+ zope.interface.implements(zc.zservertracelog.interfaces.ITraceLog)
+
+ extension_id = None
+ trace_code = None
+
+ def __init__(self, channel):
+ self.channel_id = id(channel)
+
+ 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):
- self._Channel__B = now()
+ self._Channel__B = datetime.datetime.now()
zope.server.http.httprequestparser.HTTPRequestParser.__init__(self, x)
+
class Channel(zope.server.http.httpserverchannel.HTTPServerChannel):
parser_class = Parser
def handle_request(self, parser):
- logger.info("B %s %s %s %s", id(self), parser.__B,
- parser.command, parser.path)
- logger.info("I %s %s %s", id(self), now(),
- parser.content_length)
+ logger = TraceLog(self)
+ _log(logger, 'B', '%s %s' % (parser.command, parser.path), parser.__B)
+ _log(logger, 'I', str(parser.content_length))
zope.server.http.httpserverchannel.HTTPServerChannel.handle_request(
self, parser)
@@ -54,9 +113,13 @@
channel_class = Channel
+ def __init__(self, *args, **kwargs):
+ super(Server, self).__init__(*args, **kwargs)
+
def executeRequest(self, task):
"""Overrides HTTPServer.executeRequest()."""
- logger.info("C %s %s", id(task.channel), now())
+ logger = TraceLog(task.channel)
+ _log(logger, 'C')
env = task.getCGIEnvironment()
env['wsgi.input'] = task.request_data.getBodyStream()
@@ -73,8 +136,8 @@
try:
response = self.application(env, start_response)
except Exception, v:
- logger.info("A %s %s Error: %s", id(task.channel), now(), v)
- logger.info("E %s %s", id(task.channel), now())
+ _log(logger, 'A', 'Error: %s' % v)
+ _log(logger, 'E')
raise
else:
accumulated_headers = getattr(task, 'accumulated_headers') or ()
@@ -85,28 +148,32 @@
length = length[0]
else:
length = '?'
- logger.info("A %s %s %s %s", id(task.channel), now(),
- getattr(task, 'status', '?'), length)
+
+ _log(logger, 'A', '%s %s' % (getattr(task, 'status', '?'), length))
+
try:
task.write(response)
except Exception, v:
- logger.info("E %s %s Error: %s", id(task.channel), now(), v)
+ _log(logger, 'E', 'Error: %s' % v)
raise
else:
- logger.info("E %s %s", id(task.channel), now())
+ _log(logger, 'E')
+
http = servertype.ServerType(
Server,
WSGIPublisherApplication,
CommonAccessLogger,
8080, True)
+
pmhttp = servertype.ServerType(
wsgihttpserver.PMDBWSGIHTTPServer,
WSGIPublisherApplication,
CommonAccessLogger,
8013, True)
+
@zope.component.adapter(zope.app.appsetup.interfaces.IProcessStartingEvent)
def started(event):
- logger.info("S 0 %s", now())
+ tracelog.info('S 0 %s', _format_datetime(datetime.datetime.now()))
More information about the Checkins
mailing list