#44 need to log request/response
Closed: Fixed None Opened 5 years ago by jdennis.

During development and when investigating bugs it can help immensely if one can log the HTTP requests and responses. This is not as easy as one might think.

  • Transactions are required to occur on an encrypted channel (e.g. SSL/TLS).

  • Browser tools (e.g. Firebug in Firefox) sometimes drop parts of the client/server dialog.

  • You may not be using a browser (i.e. SAML ECP)

  • Wireshark is difficult to set up for SSL and capture the relevant dialog. Wireshark cannot decrypt many of the contemporary SSL configurations because of the ciphers in use and PFS, one has to "dumb down" the SSL connection parameters before Wireshark can even decode the data, even then it's quite awkward to work with.

  • If Ipsilon is embedded in the Apache web server one can use the mod_dumpio module that logs all traffic. But this exceptionally verbose and requires post processing the log file to extract the dumpio messages from the rest of the log data and then reassemble those fragments back into HTTP messages. Plus this only works if one is using Apache.

Ipsilon is written using the cherrypy web framework. cherrypy allows you register functions that run at specific parts of the request pipeline. In cherrypy parlance these are called "tools", a term more familiar to developers would be "hooks". We should be able to register a hook to log the incoming request and outgoing response. This is the preferred approach because it does not depend on client tools, it occurs right inside Ipsilon, does not depend on the "server" hosting Ipsilon, does not involve SSL/TLS decoding, and allows for nicer formatting because we have higher level knowledge of the request/response data.

Attached is a patch which implements the cherrypy hook necessary to log a request/response pair.

While in theory writing such a hook sounded straight forward and easy it turned out to be far more complicated than anticipated. There are no simple hooks for when data is read off the wire or written back out. One has to know the internals of cherrypy and deal with how it internal operations read data and generate data for output. This is documented in the source code comments. It took several days to get this working but ability to see requests and responses is well worth it and a valuable addition.

The request/response logging can be enabled/disabled via a simple cherrypy configuration option.

I will also attach a sample log captured during an Ipsilon SAML SSO operation.


sample log showing request/response logging. (note: the exceptionally long URL's are a consequence of SAML)
error_log_clean.txt

available in git://fedorapeople.org/~jdennis/ipsilon.git under the req_resp_log topic branch

Fields changed

owner: simo => jdennis
status: new => assigned

Fields changed

resolution: => fixed
status: assigned => closed

Fields changed

resolution: fixed =>
status: closed => reopened

Fields changed

summary: need to log request/respose => need to log request/response

Fields changed

milestone: => 1.0 m1
patch_available: => 0
status: reopened => assigned

Pushed to master.

Commit id: e85f190

resolution: => fixed
status: assigned => closed

Fields changed

rhbz: => 0

Metadata Update from @nkinder:
- Issue assigned to jdennis
- Issue set to the milestone: 1.0 m1

3 years ago

Login to comment on this ticket.

Metadata