Replace debuglevel-related logic with logging

[demianbrecht]

BPO	24255
Nosy	@vsajip, @bitdancer, @berkerpeksag, @demianbrecht, @CuriousLearner, @xgid, @sloonz, @sosey, @aldwinaldwin
PRs	gh-68443: Replace debug level-related logic in http client with logging #8633
Files	http-client-logging.patch http-client-logging-v2.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2015-05-21.06:25:54.911>
labels = ['3.7', '3.8', 'type-feature', 'library', 'easy']
title = 'Replace debuglevel-related logic with logging'
updated_at = <Date 2019-06-17.08:18:45.993>
user = 'https://github.com/demianbrecht'

bugs.python.org fields:

activity = <Date 2019-06-17.08:18:45.993>
actor = 'aldwinaldwin'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2015-05-21.06:25:54.911>
creator = 'demian.brecht'
dependencies = []
files = ['39651', '47727']
hgrepos = []
issue_num = 24255
keywords = ['patch', 'easy']
message_count = 19.0
messages = ['243734', '243750', '244919', '244960', '312426', '316571', '322897', '322958', '322968', '322977', '322983', '322985', '322986', '322989', '323239', '323249', '323254', '323268', '345816']
nosy_count = 11.0
nosy_names = ['vinay.sajip', 'r.david.murray', 'berker.peksag', 'demian.brecht', 'erynofwales', 'CuriousLearner', 'xgdomingo', 'sloonz', 'msosey', 'Conrad Ho', 'aldwinaldwin']
pr_nums = ['8633']
priority = 'normal'
resolution = None
stage = 'needs patch'
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue24255'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[demianbrecht]

Far too many times have I wished that changing the logging output in http.client was controllable through logging configuration rather than code changes modifying a connection's debuglevel.

It would be nice if the http package was brought up to date and had debuglevel-related code replaced with logging and sane logging was added throughout.

[bitdancer]

+1

[erynofwales]

Hi. This is my first issue, but I'd be willing to have a go at updating this module. Do either of you have specific ideas about what changes you want here?

My thought was to import logging, create a logger object, and start by replacing all the self.debuglevel stuff with appropriate log statements. Does that make sense? Do each of the classes need separate loggers, or is just one module-level logger enough?

[erynofwales]

Here's a patch that replaces all the debuglevel stuff with logging. There's a single module-level logger that handles it all.

I wasn't sure if it would be okay to break API compatibility, so I kept the debuglevel flag and the set_debuglevel() method even though they don't do anything.

Most of the information that was being print()ed is still there, but I cleaned it up a little and added a few more messages.

The INFO level messages are pretty sparse, with DEBUG providing a lot more raw data from the request.

[CuriousLearner]

Hey Erin,

Can you please convert your patch to a PR on Github?

[sosey]

I'm going to work on this one since the original reporter last commented 3 years ago. I took a quick look at how the other modules are handling logging to see if I could make it consistent, and they all do it a bit differently. It might be worthwhile considering normalizing logging across the modules at some point. I'm working with the python 3.8 currently on master.

[ConradHo]

Hi,

I have referenced the original patch and created an updated patch that uses the logging module + f-strings in place of the print statements in the http.client module. Also updated the relevant tests for print/logging in test_httplib to reflect these changes.

The HTTPHandlerTest testcase from test_logging was also affected. In the testcase, it gets a logger with name 'http' and adds a logging.HTTPHandler to it. In our patch, we create a http.client logger, which happens to be considered a child of this testcase logger under the logger naming hierarchy.

This causes http.client logging events to propagate up to the 'http' logger and for the testcase to loop infinitely (ie. the HTTPHandler calls http.client functions internally. These functions log events using the http.client logger, which propagate up to the testcase http logger which calls HttpHandler again).

I have simply changed the testcase getLogger name to not be 'http' and clash with that http.client module logger.

[bitdancer]

Conrad: thanks for the effort, but using f-strings with logging is counterproductive. The idea behind logging is that the logged strings are not materialized unless something actually wants to output them. Using fstrings means you are doing all the work of formatting the string regardless of whether or not the string is actually going to get written anywhere. The original patch also retains the debug guards that minimize overhead when debugging is not turned on, which it doesn't look like your patch does.

Regardless, what we need at this stage is a github PR, not a patch :)

[erynofwales]

Hi, it sounds like my original patch is the preferred approach. I can put up a GitHub PR for that.

[erynofwales]

Actually, I spoke too soon. My current employer isn't too keen on us contributing to open source, so I can't do this. Sorry!

[CuriousLearner]

That's okay Eryn. We really appreciate all your help.

I will take this patch forward :)

[ConradHo]

Thanks Eryn!

@sanyam if you apply the original patch directly that will currently result in some merge failures, and there are test fixes etc that I did on the second patch. Think we should combine them.

I just made the chgs suggested by David on my own forked repo. Do you want me to submit a PR directly?