ipsilon/util/log.py

   1 # Copyright (C) 2014 Ipsilon Project Contributors
   2 #
   3 # See the file named COPYING for the project license
   4
   5 import cherrypy
   6 import inspect
   7 import cStringIO
   8
   9 def log_request_response():
  10     '''Log the contents of the request and subsequent response.
  11
  12     This is run as a tool hook and should be run as the last hook
  13     (on_end_resource) just before the server writes the response to
  14     the client. The tool is registered like this:
  15
  16     cherrypy.tools.log_request_response = \
  17         cherrypy.Tool('on_end_resource', log_request_response)
  18
  19     Then the logging can be enabled or disabled via the config option,
  20     for example to turn the logging on via a config dict add this
  21     key/value pair:
  22
  23     'tools.log_request_response.on': True,
  24
  25     or for a config file add this line:
  26
  27     tools.log_request_response.on = True
  28
  29     At first blush it would seem easy to log the request received and
  30     the response emitted, just hook those locations and output the raw
  31     data. Unfortunately there are no such locations in cherrypy where
  32     you have access to the raw input and output data. The complicating
  33     factors are:
  34
  35     * Input data is consumed by the Request object off a file object
  36       which cannot seek back (i.e. rewind), once the data is read it
  37       cannot be read again. Therefore any attempt to log the raw input
  38       will starve read operations done by the Request object to read
  39       the headers and body.
  40
  41     * Automatic consumption and processing of the body contents is
  42       enabled by default (controlled by the
  43       request.process_request_body config option). You generally do
  44       not want to turn these automatic request processors off because
  45       they provide valuable input processing useful to the request
  46       processing pipeline (e.g. when Content-Type is
  47       application/x-www-form-urlencoded, or multipart/form-data or
  48       multipart). Most cherrypy page handlers expect this
  49       pre-processing to have been performed and the 'cooked' data to
  50       be availabe on the Request object. Thus rather than logging the
  51       raw input HTTP which will have been consumed by the request
  52       processing logic we are forced into logging only the 'cooked'
  53       values available to us after the request has been read and
  54       processed.
  55
  56     * The response body may not be available if response streaming is
  57       enabled. This is because control is passed directly to the
  58       object writing the data to the client bypassing the normal
  59       cherrypy hooks. Fortunately streaming is not recommended and we
  60       can expect it will be disabled. When streaming is disabled the
  61       response body can be composed as:
  62
  63         - string
  64         - list of strings
  65         - a generator yielding chunks of strings
  66
  67       When the response body is a string or list of strings logging
  68       the body and then passing down the pipeline to be written to the
  69       client is trivial. However when part of the body is produced by
  70       a generator we must run the generator to produce that part of
  71       the body and store it as a string. This is an issue equivalent
  72       to not being able to re-read a file object as seen in the input
  73       situation. Once the generator has run it cannot be run
  74       again. Therefore we consume all the body output, store it in a
  75       string, log it and then replace the request body contents with
  76       the body string we formed. It's this body string which is
  77       subsequently sent down the processing pipeline to be written to
  78       the client.
  79
  80     '''
  81
  82     #--- Begin local functions ---
  83
  84     def indent_text(text, level=0, indent='    '):
  85         '''
  86         Input is a block of text potentially containing newlines which
  87         seperate the text into a sequence of lines. The text block is
  88         split into individual lines and indented according to the
  89         indentation level. The width of the indent is controlled by
  90         the optional indent parameter.
  91
  92         The result is a single block of text where each of the
  93         original lines of text are indented.
  94         '''
  95
  96         f = cStringIO.StringIO()
  97
  98         lines = text.split('\n')
  99
 100         # Do not output trailing newline
 101         if lines and lines[-1] == '':
 102             lines.pop(-1)
 103
 104         for line in lines:
 105             f.write(indent*level)
 106             f.write(line)
 107             f.write('\n')
 108
 109         string = f.getvalue()
 110         f.close()
 111         return string
 112
 113     def print_part(part):
 114         '''
 115         Format a cherrypy._cpreqbody.Part object into a string.
 116
 117         When the request Content-Type is a multipart cherrypy splits
 118         each part of the multipart into a Part object containing
 119         information about the part and it's content.
 120         '''
 121         f = cStringIO.StringIO()
 122
 123         f.write(indent_text('Name = %s\n' % part.name))
 124         if part.headers:
 125             f.write(indent_text('Headers:\n'))
 126             for name, value in part.headers.items():
 127                 f.write(indent_text('%s: %s\n' % (name, value), 1))
 128
 129         f.write(indent_text("Body:\n"))
 130         f.write(indent_text(part.fullvalue(), 1))
 131
 132         string = f.getvalue()
 133         f.close()
 134         return string
 135
 136     def collapse_body(body):
 137         '''The cherrypy response body can be:
 138
 139         * string
 140         * list of strings
 141         * generator yielding a string
 142
 143         Generators are typically used for file contents but any
 144         cherrypy response is permitted to use a generator to provide
 145         the body of the response.
 146
 147         Strings and lists of strings are immediately available and
 148         stored in the request object. During normal cherrypy
 149         processing when writing the response to the client response
 150         data which is provided by a generator will be iterated over
 151         and written to the client. In order for us to be able to log
 152         all the response data prior to it being sent to the client we
 153         must also iterate over the generator provided content, however
 154         this exhausts the generator making it unavailable to be
 155         written to the client.
 156
 157         To solve this problem we collect all the response data. Now we
 158         have the full body contents, we can log it and then set this
 159         as the new body contents for remainder of the processing
 160         pipeline to act upon (i.e. sent to the client)
 161         '''
 162         f = cStringIO.StringIO()
 163
 164         for chunk in body:
 165             f.write(chunk)
 166
 167         string = f.getvalue()
 168         f.close()
 169         return string
 170
 171     #--- End local functions ---
 172
 173     f = cStringIO.StringIO()
 174     request = cherrypy.serving.request
 175     remote = request.remote
 176
 177     #
 178     # Log the Request
 179     #
 180     f.write(indent_text("<Request> [%s] %s\n" % \
 181                       (remote.name or remote.ip, request.request_line), 0))
 182
 183     # Request Headers
 184     if request.headers:
 185         f.write(indent_text("Headers:\n", 1))
 186         for name, value in request.headers.items():
 187             f.write(indent_text("%s: %s\n" % (name, value), 2))
 188
 189     # Request parameters from URL query string and
 190     # x-www-form-urlencoded POST data
 191     if request.body.params:
 192         f.write(indent_text("Params:\n", 1))
 193         for name, value in request.body.params.items():
 194             # Multi-valued paramater is in a list
 195             if isinstance(value, list):
 196                 for i, item in enumerate(value):
 197                     # Might be a multipart Part object, if so format it
 198                     if isinstance(item, cherrypy._cpreqbody.Part):
 199                         f.write(indent_text("%s[%s]:\n" % (name, i), 2))
 200                         f.write(indent_text(print_part(item), 3))
 201                     else:
 202                         # Not a mulitpart, just write it as a string
 203                         f.write(indent_text("%s[%s]: %s\n" % (name, i, item), 2))
 204             else:
 205                 # Just a string value
 206                 f.write(indent_text("%s: %s\n" % (name, value), 2))
 207
 208     # If the body is multipart format each of the parts
 209     if request.body.parts:
 210         f.write(indent_text("Body Parts:\n"))
 211         for i, part in enumerate(request.body.parts):
 212             f.write(indent_text("Part %s name=%s:\n" % (i, part.name), 3))
 213             f.write(indent_text(print_part(part), 4))
 214
 215     #
 216     # Log the Response
 217     #
 218     response = cherrypy.response
 219     f.write(indent_text("<Response> %s\n" % response.status, 0))
 220
 221     # Log the response headers
 222     if response.header_list:
 223         f.write(indent_text("Headers:\n", 1))
 224         for name, value in response.header_list:
 225             f.write(indent_text("%s: %s\n" % (name, value), 2))
 226
 227     # Log the response body
 228     #
 229     # We can only do this if the response is not streaming because we have
 230     # no way to hook the streaming content.
 231     f.write(indent_text("Body:\n", 1))
 232
 233     if response.stream:
 234         f.write(indent_text("body omitted because response is streaming\n", 2))
 235     else:
 236         response.body = collapse_body(response.body)
 237         for chunk in response.body:
 238             f.write(indent_text(chunk, 2))
 239
 240     string = f.getvalue()
 241     f.close()
 242     print string
 243
 244 cherrypy.tools.log_request_response = cherrypy.Tool('on_end_resource', log_request_response)
 245
 246
 247 class Log(object):
 248
 249     def debug(self, fact):
 250         if cherrypy.config.get('debug', False):
 251             s = inspect.stack()
 252             cherrypy.log('DEBUG(%s): %s' % (s[1][3], fact))
 253
 254     # for compatibility with existing code
 255     _debug = debug
 256
 257     def log(self, fact):
 258         cherrypy.log(fact)
 259
 260     def error(self, fact):
 261         cherrypy.log.error('ERROR: %s' % fact)