Skip to main content

Zope 3 tracelog implementation for zserver

Project description

=======================
Zope 3/ZServer tracelog
=======================

This package implements a Zope2-style (extended) tracelog. A tracelog
is a kind of access log that records several low-level events for each
request. Each log entry starts with a record type, a request
identifier and the time. Some log records have additional data.


Trace Codes
===========

- Request begins:

B -1214390740 2007-04-27T20:16:55.582940 GET /

Includes the request method and path.

- Got request input:

I -1214390740 2007-04-27T20:16:55.605791 0

Includes the request content length.

- Entered application thread:

C -1214390740 2007-04-27T20:16:55.703829

- Application done:

A -1223774356 2007-04-27T20:16:55.890371 500 84

Includes the response content length.

- Request done:

E -1223774356 2007-04-27T20:16:55.913855

In addition, application startup is logged with an 'S' record:

S 0 2007-04-27T20:24:29.013922

Tracelog extension records are prefixed with a '-':

- -1223774356 2008-09-12T15:51:05.559302 zc.example.extension message

To create a trace log, include the zc.zservertracelog package in your
site ZCML configuration. Also, define a logger section in zope.conf::

<logger>
name zc.zservertracelog
propagate false

<logfile>
format %(message)s
path /home/jim/p/zc.zservertracelog/dev/trace.log
</logfile>

</logger>

Where, of course, you'll need to specify a log file path.

The analysis script, tracereport, can be used to analyze the trace
log. I recommend the html output option.


Detailed Documentation
**********************


================
ZServer TraceLog
================

A tracelog is a kind of access log that records several low-level events for
each request. Each log entry starts with a record type, a request identifier
and the time. Some log records have additional data.

>>> import zc.zservertracelog.tracelog
>>> import zope.app.appsetup.interfaces

For these examples, we'll add a log handler that outputs to standard out.

>>> import logging
>>> import sys
>>> stdout_handler = logging.StreamHandler(sys.stdout)

The logger's name is not the package name, but "zc.tracelog" for backward
compatability.

>>> logger = logging.getLogger('zc.tracelog')
>>> logger.setLevel(logging.INFO)
>>> logger.addHandler(stdout_handler)


Server Startup
==============

There is an event handler to log when the Z server starts.

>>> zc.zservertracelog.tracelog.started(
... zope.app.appsetup.interfaces.ProcessStarting())
S 0 2008-08-26 11:55:00.000000


Tracing Applications
====================

The tracelog machinery is implemented as a WSGI layer, so we'll pass a fake
WSGI application to tracelog for these examples.

>>> faux_app = FauxApplication()

Now, let's create an instance of the tracelog server.

>>> addr, port = '127.0.0.1', 12345

>>> trace_server = zc.zservertracelog.tracelog.Server(
... faux_app, None, addr, port)

Let's also define a convenience function for processing requests.

>>> def invokeRequest(req):
... channel = trace_server.channel_class(trace_server, None, addr)
... channel.received(req)

Process a simple request.

>>> req1 = """\
... GET /test-req1 HTTP/1.1
... Host: www.example.com
...
... """

>>> invokeRequest(req1)
B 23423600 2008-08-27 10:54:08.000000 GET /test-req1
I 23423600 2008-08-27 10:54:08.000000 0
C 23423600 2008-08-27 10:54:08.000000
A 23423600 2008-08-27 10:54:08.000000 200 ?
E 23423600 2008-08-27 10:54:08.000000


Application Errors
==================

The tracelog will also log application errors. To show this, we'll set up
our test application to raise an error when called.

>>> def app_failure(*args, **kwargs):
... raise Exception('oh noes!')
>>> faux_app.app_hook = app_failure

Invoking the request produces log entries for every trace point, and the
application error is written to the *Application End (A)* trace entry.

>>> try:
... invokeRequest(req1)
... except:
... pass
B 21663984 2008-09-02 11:19:26.000000 GET /test-req1
I 21663984 2008-09-02 11:19:26.000000 0
C 21663984 2008-09-02 11:19:26.000000
A 21663984 2008-09-02 11:19:26.000000 Error: oh noes!
E 21663984 2008-09-02 11:19:26.000000


Response Errors
===============

The tracelog also handles errors that can be generated when writing to the
response. To show this, we'll set up our test application to return a
response that produces an error when written to.

>>> def response_of_wrong_type(*args, **kwargs):
... return object()
>>> faux_app.app_hook = response_of_wrong_type

Invoking the request produces log entries for every trace point, and the
error is written to the *Request End (E)* trace entry.

>>> try:
... invokeRequest(req1)
... except:
... pass
B 21651664 2008-09-02 13:59:02.000000 GET /test-req1
I 21651664 2008-09-02 13:59:02.000000 0
C 21651664 2008-09-02 13:59:02.000000
A 21651664 2008-09-02 13:59:02.000000 200 ?
E 21651664 2008-09-02 13:59:02.000000 Error: iteration over non-sequence

Let's clean up before moving on.

>>> faux_app.app_hook = None


Log Messages Containing Line Breaks
===================================

Messages to the tracelog that contain newline characters will not split a log
entry into multiple lines.

>>> req2 = """\
... GET /test-req2/%0Aohnoes/ HTTP/1.1
... Host: www.example.com/linebreak
...
... """

>>> invokeRequest(req2)
B 21598352 2008-09-12 11:40:27.000000 GET /test-req2/\nohnoes/
I 21598352 2008-09-12 11:40:27.000000 0
C 21598352 2008-09-12 11:40:27.000000
A 21598352 2008-09-12 11:40:27.000000 200 ?
E 21598352 2008-09-12 11:40:27.000000


Request Query Strings
=====================

The tracelog preserves request query strings.

>>> req3 = """\
... GET /test-req3/?creature=unicorn HTTP/1.1
... Host: www.example.com/query-string
...
... """

>>> invokeRequest(req3)
B 21598352 2008-09-12 11:40:27.000000 GET /test-req3/?creature=unicorn
I 21598352 2008-09-12 11:40:27.000000 0
C 21598352 2008-09-12 11:40:27.000000
A 21598352 2008-09-12 11:40:27.000000 200 ?
E 21598352 2008-09-12 11:40:27.000000

Empty query strings are also preserved.

>>> req4 = """\
... GET /test-req4/? HTTP/1.1
... Host: www.example.com/empty-query-string
...
... """

>>> invokeRequest(req4)
B 21598352 2008-09-12 11:40:27.000000 GET /test-req4/?
I 21598352 2008-09-12 11:40:27.000000 0
C 21598352 2008-09-12 11:40:27.000000
A 21598352 2008-09-12 11:40:27.000000 200 ?
E 21598352 2008-09-12 11:40:27.000000


Adding Additional Entries to the Trace Log
==========================================

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.

Here is an example application that adds a custom entry to the tracelog.

>>> def noisy_app(environ, start_response):
... logger = environ['zc.zservertracelog.interfaces.ITraceLog']
... logger.log('beep! beep!')
>>> faux_app.app_hook = noisy_app

>>> invokeRequest(req1)
B 21569456 2008-09-12 15:51:05.000000 GET /test-req1
I 21569456 2008-09-12 15:51:05.000000 0
C 21569456 2008-09-12 15:51:05.000000
- 21569456 2008-09-12 15:51:05.000000 beep! beep!
A 21569456 2008-09-12 15:51:05.000000 200 ?
E 21569456 2008-09-12 15:51:05.000000


=========
Changes
=========

1.1.4 (2009-03-25)
------------------

- put user names in access log


1.1.3 (2009-03-25)
------------------

- sub-second resolution in timestamps


1.1.1 (2008-11-21)
------------------

- switch back to logger name zc.tracelog to maintain backward compatibility.


1.1.0 (2008-10-31)
------------------

- fixed tracelog extension format so that it doesn't conflict with the Zope2
trace code for server shutdown.

- added *summary-only* and *summary-lines* options to tracereport.

- added shading of alternating rows in tracereport table output.

- fixed a documentation error for loghandler configuration.


0.4 (2008-10-09)
----------------

- added automated tests.

- 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.

Project details


Download files

Download the file for your platform. If you're not sure which to choose, learn more about installing packages.

Source Distribution

zc.zservertracelog-1.1.4.tar.gz (13.6 kB view hashes)

Uploaded Source

Supported by

AWS AWS Cloud computing and Security Sponsor Datadog Datadog Monitoring Fastly Fastly CDN Google Google Download Analytics Microsoft Microsoft PSF Sponsor Pingdom Pingdom Monitoring Sentry Sentry Error logging StatusPage StatusPage Status page