zc.zservertracelog 1.1.3

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