1 # Copyright (C) 2014 Ipsilon Project Contributors
3 # See the file named COPYING for the project license
9 def log_request_response():
10 '''Log the contents of the request and subsequent response.
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:
16 cherrypy.tools.log_request_response = \
17 cherrypy.Tool('on_end_resource', log_request_response)
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
23 'tools.log_request_response.on': True,
25 or for a config file add this line:
27 tools.log_request_response.on = True
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
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
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
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:
65 - a generator yielding chunks of strings
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
82 #--- Begin local functions ---
84 def indent_text(text, level=0, indent=' '):
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.
92 The result is a single block of text where each of the
93 original lines of text are indented.
96 f = cStringIO.StringIO()
98 lines = text.split('\n')
100 # Do not output trailing newline
101 if lines and lines[-1] == '':
105 f.write(indent*level)
109 string = f.getvalue()
113 def print_part(part):
115 Format a cherrypy._cpreqbody.Part object into a string.
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.
121 f = cStringIO.StringIO()
123 f.write(indent_text('Name = %s\n' % part.name))
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))
129 f.write(indent_text("Body:\n"))
130 f.write(indent_text(part.fullvalue(), 1))
132 string = f.getvalue()
136 def collapse_body(body):
137 '''The cherrypy response body can be:
141 * generator yielding a string
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.
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.
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)
162 f = cStringIO.StringIO()
167 string = f.getvalue()
171 #--- End local functions ---
173 f = cStringIO.StringIO()
174 request = cherrypy.serving.request
175 remote = request.remote
180 f.write(indent_text("<Request> [%s] %s\n" % \
181 (remote.name or remote.ip, request.request_line), 0))
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))
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))
202 # Not a mulitpart, just write it as a string
203 f.write(indent_text("%s[%s]: %s\n" % (name, i, item), 2))
205 # Just a string value
206 f.write(indent_text("%s: %s\n" % (name, value), 2))
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))
218 response = cherrypy.response
219 f.write(indent_text("<Response> %s\n" % response.status, 0))
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))
227 # Log the response body
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))
234 f.write(indent_text("body omitted because response is streaming\n", 2))
236 response.body = collapse_body(response.body)
237 for chunk in response.body:
238 f.write(indent_text(chunk, 2))
240 string = f.getvalue()
244 cherrypy.tools.log_request_response = cherrypy.Tool('on_end_resource', log_request_response)
249 def debug(self, fact):
250 if cherrypy.config.get('debug', False):
252 cherrypy.log('DEBUG(%s): %s' % (s[1][3], fact))
254 # for compatibility with existing code
260 def error(self, fact):
261 cherrypy.log.error('ERROR: %s' % fact)