classification
Title: [httplib] logging information for request is not pretty printed
Type: enhancement Stage: resolved
Components: Library (Lib) Versions: Python 3.5
process
Status: closed Resolution: duplicate
Dependencies: Superseder: Replace debuglevel-related logic with logging
View: 24255
Assigned To: Nosy List: berker.peksag, demian.brecht, mcepl, orsenthil, r.david.murray
Priority: normal Keywords:

Created on 2013-12-07 10:44 by mcepl, last changed 2015-10-03 04:07 by berker.peksag. This issue is now closed.

Files
File name Uploaded Description Edit
urllib2-kerberos-log.txt mcepl, 2013-12-07 10:44 example log
Messages (6)
msg205446 - (view) Author: Matej Cepl (mcepl) * Date: 2013-12-07 10:44
looking at
http://hg.python.org/cpython/file/543c76769c14/Lib/http/client.py#l847
(logging in HTTPConnection.send method; but this code has been same since like forever) I see that the HTTP request is NOT pretty printed:

     if self.debuglevel > 0:
         print("send:", repr(data))

whereas response in effect (because every header is printed separately) is. Wouldn't it be better to pretty print the request as well?

Otherwise I get quite unreadable debugging logs like the following (notice how much response is more readable than request).

It seems to me that proper solution could be just to replace repr() here with something more readable. Wouldn't just str() help? Barring that we can go all the way to pprint.pformat().
msg205490 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2013-12-07 21:38
I am not an expert in web stuff, but off the top of my head, it seems that requests should be handled the same way as responses.
msg220829 - (view) Author: Senthil Kumaran (orsenthil) * (Python committer) Date: 2014-06-17 14:01
I believe, repr() is the correct call here. You should know the proper  end of line characters like \n, \r\n which were sent in the request while debugging. A pretty print here, while look good, might remove that capability and thus may not add any value in my opinion.
msg220837 - (view) Author: Demian Brecht (demian.brecht) * (Python triager) Date: 2014-06-17 15:22
I have a few questions about this one:

1. Why is print used to begin with? Surely this should use debug logging. Using print, you lose the benefits of logging: Timestamps, if used in the configured logger, can be invaluable to match up against logs generated by another server. There's also the additional utilities such as logging handlers that you don't get when using print.

1a. If logging should be used instead of debuglevel, it would stand to reason that debuglevel would be useless from the context of httplib. However, as there may be custom implementations that are dependent on this parameter, it should remain and be passed through as to not break backwards compatibility.

2. What is the preferred output: Pretty printed or raw values? As Senthil mentions, to me, seeing the raw request/response is much more valuable than seeing a pretty representation. Additionally, if you're logging a fair number of requests/responses, pretty printed output would make for an eyesore pretty quickly (at least it would for me).

3. I might be missing something, but it seems to me that receiving prints out the status line and headers while parsing per-line reads through the fp, but sending just sends un-parsed chunked data, so differentiating between status line, headers and body would take some additional work. Additionally, if the data being sent originates from a file-like object, readline() is not used as it is when receiving data, but it seems to naively send the data in chunks of what should be system page size.


To address the specific problem reported (make the receive/send logs consistent), I think that an easy, interim solution would be to buffer the expected output log during receiving when debuglevel > 0 until after the headers are parsed and then flush through a print() or logging.debug(). I'd have to try it out to be sure, but I believe this would still leave the inconsistency of request bodies being logged but not response, but that could be tackled independently of this issue.
msg220838 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2014-06-17 15:36
It doesn't use logging because (I think) logging didn't exist when it was implemented.  Whether or not we want to change that is a more complicated question, I think.  Probably we don't, for backward compatibility reasons.
msg252190 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2015-10-03 04:07
Closing as a duplicate of issue 24255.
History
Date User Action Args
2015-10-03 04:07:42berker.peksagsetstatus: open -> closed

superseder: Replace debuglevel-related logic with logging

nosy: + berker.peksag
messages: + msg252190
resolution: duplicate
stage: test needed -> resolved
2014-06-17 15:36:25r.david.murraysetmessages: + msg220838
2014-06-17 15:31:40terry.reedysetnosy: - terry.reedy
2014-06-17 15:22:23demian.brechtsetmessages: + msg220837
2014-06-17 14:01:21orsenthilsetmessages: + msg220829
2014-06-17 06:00:04demian.brechtsetnosy: + demian.brecht
2013-12-07 21:38:24terry.reedysetversions: + Python 3.5
nosy: + terry.reedy, r.david.murray, orsenthil

messages: + msg205490

type: enhancement
stage: test needed
2013-12-07 10:44:40mceplcreate