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