From afeb73cf81f3b69bee5835bf99cf05a4029281f3 Mon Sep 17 00:00:00 2001 From: Sanyam Khurana Date: Fri, 14 Nov 2025 05:17:12 +0530 Subject: [PATCH] bpo-24255: Replace debug prints with logging in http.client Replace debuglevel-based print statements with Python's standard logging module for better integration with logging frameworks and log aggregation tools like Sentry. Uses % formatting consistently for better log pattern matching in aggregation tools. --- Lib/http/client.py | 127 ++++++++++++------ Lib/test/test_httplib.py | 26 +++- Lib/test/test_logging.py | 9 +- .../2025-12-07-00-00-00.bpo-24255.IZcKUO.rst | 1 + 4 files changed, 114 insertions(+), 49 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2025-12-07-00-00-00.bpo-24255.IZcKUO.rst diff --git a/Lib/http/client.py b/Lib/http/client.py index 73c3256734a64f..b61e7317a9855f 100644 --- a/Lib/http/client.py +++ b/Lib/http/client.py @@ -73,6 +73,7 @@ import errno import http import io +import logging import re import socket import sys @@ -162,6 +163,8 @@ # servers will otherwise respond with a 411 _METHODS_EXPECTING_BODY = {'PATCH', 'POST', 'PUT'} +_log = logging.getLogger(__name__) + def _encode(data, name='data'): """Call data.encode("latin-1") but show a better error message.""" @@ -285,7 +288,7 @@ def __init__(self, sock, debuglevel=0, method=None, url=None): self.headers = self.msg = None # from the Status-Line of the response - self.version = _UNKNOWN # HTTP-Version + self.version = _UNKNOWN # HTTP-Version self.status = _UNKNOWN # Status-Code self.reason = _UNKNOWN # Reason-Phrase @@ -298,8 +301,7 @@ def _read_status(self): line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1") if len(line) > _MAXLINE: raise LineTooLong("status line") - if self.debuglevel > 0: - print("reply:", repr(line)) + _log.info("reply: %r", line) if not line: # Presumably, the server closed the connection before # sending a valid response. @@ -325,6 +327,7 @@ def _read_status(self): raise BadStatusLine(line) except ValueError: raise BadStatusLine(line) + _log.info('Received response: %s %s', status, reason.strip()) return version, status, reason def begin(self, *, _max_headers=None): @@ -339,8 +342,7 @@ def begin(self, *, _max_headers=None): break # skip the header from the 100 response skipped_headers = _read_headers(self.fp, _max_headers) - if self.debuglevel > 0: - print("headers:", skipped_headers) + _log.info("headers: %s", skipped_headers) del skipped_headers self.code = self.status = status @@ -357,9 +359,9 @@ def begin(self, *, _max_headers=None): self.fp, _max_headers=_max_headers ) - if self.debuglevel > 0: + if _log.isEnabledFor(logging.INFO): for hdr, val in self.headers.items(): - print("header:", hdr + ":", val) + _log.info("Received header: ('%s': '%s')", hdr, val) # are we using the chunked-style of transfer encoding? tr_enc = self.headers.get("transfer-encoding") @@ -389,16 +391,14 @@ def begin(self, *, _max_headers=None): # does the body have a fixed length? (of zero) if (status == NO_CONTENT or status == NOT_MODIFIED or - 100 <= status < 200 or # 1xx codes - self._method == "HEAD"): + 100 <= status < 200 or # 1xx codes + self._method == "HEAD"): self.length = 0 # if the connection remains open, and we aren't using chunked, and # a content-length was not provided, then assume that the connection # WILL close. - if (not self.will_close and - not self.chunked and - self.length is None): + if (not self.will_close and not self.chunked and self.length is None): self.will_close = True def _check_close(self): @@ -437,7 +437,7 @@ def _close_conn(self): def close(self): try: - super().close() # set "closed" flag + super().close() # set "closed" flag finally: if self.fp: self._close_conn() @@ -506,6 +506,7 @@ def read(self, amt=None): raise self.length = 0 self._close_conn() # we read everything + self._log_bytes_read(len(s)) return s def readinto(self, b): @@ -540,6 +541,7 @@ def readinto(self, b): self.length -= n if not self.length: self._close_conn() + self._log_bytes_read(n) return n def _read_next_chunk_size(self): @@ -549,7 +551,7 @@ def _read_next_chunk_size(self): raise LineTooLong("chunk size") i = line.find(b";") if i >= 0: - line = line[:i] # strip chunk-extensions + line = line[:i] # strip chunk-extensions try: return int(line, 16) except ValueError: @@ -560,7 +562,7 @@ def _read_next_chunk_size(self): def _read_and_discard_trailer(self): # read and discard trailer up to the CRLF terminator - ### note: we shouldn't have any trailers! + # note: we shouldn't have any trailers! while True: line = self.fp.readline(_MAXLINE + 1) if len(line) > _MAXLINE: @@ -579,7 +581,7 @@ def _get_chunk_left(self): # This function returns non-zero or None if the last chunk has # been read. chunk_left = self.chunk_left - if not chunk_left: # Can be 0 or None + if not chunk_left: # Can be 0 or None if chunk_left is not None: # We are at the end of chunk, discard chunk end self._safe_read(2) # toss the CRLF at the end of the chunk @@ -624,11 +626,13 @@ def _readinto_chunked(self, b): while True: chunk_left = self._get_chunk_left() if chunk_left is None: + self._log_bytes_read(total_bytes) return total_bytes if len(mvb) <= chunk_left: n = self._safe_readinto(mvb) self.chunk_left = chunk_left - n + self._log_bytes_read(total_bytes + n) return total_bytes + n temp_mvb = mvb[:chunk_left] @@ -727,7 +731,7 @@ def _read1_chunked(self, n): if chunk_left is None or n == 0: return b'' if not (0 <= n <= chunk_left): - n = chunk_left # if n is negative or larger than chunk_left + n = chunk_left # if n is negative or larger than chunk_left read = self.fp.read1(n) self.chunk_left -= len(read) if not read: @@ -740,9 +744,9 @@ def _peek_chunked(self, n): try: chunk_left = self._get_chunk_left() except IncompleteRead: - return b'' # peek doesn't worry about protocol + return b'' # peek doesn't worry about protocol if chunk_left is None: - return b'' # eof + return b'' # eof # peek is allowed to return more than requested. Just request the # entire chunk, and truncate what we get. return self.fp.peek(chunk_left)[:chunk_left] @@ -825,6 +829,10 @@ def getcode(self): ''' return self.status + def _log_bytes_read(self, bytes_read): + _log.debug('Read %d byte%s of response data', bytes_read, + '' if bytes_read == 1 else 's') + def _create_https_context(http_version): # Function also used by urllib.request to be able to set the check_hostname @@ -897,6 +905,7 @@ def __init__(self, host, port=None, timeout=socket._GLOBAL_DEFAULT_TIMEOUT, self.__response = None self.__state = _CS_IDLE self._method = None + self._url = None self._tunnel_host = None self._tunnel_port = None self._tunnel_headers = {} @@ -953,12 +962,12 @@ def _get_hostport(self, host, port): j = host.rfind(']') # ipv6 addresses have [...] if i > j: try: - port = int(host[i+1:]) + port = int(host[i + 1:]) except ValueError: - if host[i+1:] == "": # http://foo.com:/ == http://foo.com/ + if host[i + 1:] == "": # http://foo.com:/ == http://foo.com/ port = self.default_port else: - raise InvalidURL("nonnumeric port: '%s'" % host[i+1:]) + raise InvalidURL("nonnumeric port: '%s'" % host[i + 1:]) host = host[:i] else: port = self.default_port @@ -976,6 +985,7 @@ def _wrap_ipv6(self, ip): return ip def _tunnel(self): + _log.info('Tunneling through %s:%s', self._tunnel_host, self._tunnel_port) connect = b"CONNECT %s:%d %s\r\n" % ( self._wrap_ipv6(self._tunnel_host.encode("idna")), self._tunnel_port, @@ -996,13 +1006,16 @@ def _tunnel(self): self._raw_proxy_headers = _read_headers(response.fp, self.max_response_headers) - if self.debuglevel > 0: + if _log.isEnabledFor(logging.INFO): for header in self._raw_proxy_headers: - print('header:', header.decode()) + _log.info('header: %s', header.decode()) if code != http.HTTPStatus.OK: self.close() raise OSError(f"Tunnel connection failed: {code} {message.strip()}") + _log.debug('Connection to tunnel host %s:%s succeeded', + self._tunnel_host, + self._tunnel_port) finally: response.close() @@ -1023,9 +1036,11 @@ def get_proxy_response_headers(self): def connect(self): """Connect to the host and port specified in __init__.""" + _log.debug('Opening socket to %s:%s', self.host, self.port) + sys.audit("http.client.connect", self, self.host, self.port) self.sock = self._create_connection( - (self.host,self.port), self.timeout, self.source_address) + (self.host, self.port), self.timeout, self.source_address) # Might fail in OSs that don't implement TCP_NODELAY try: self.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) @@ -1049,6 +1064,7 @@ def close(self): if response: self.__response = None response.close() + _log.info('Closed connection to %s:%s', self.host, self.port) def send(self, data): """Send 'data' to the server. @@ -1062,11 +1078,7 @@ def send(self, data): else: raise NotConnected() - if self.debuglevel > 0: - print("send:", repr(data)) - if hasattr(data, "read") : - if self.debuglevel > 0: - print("sending a readable") + if hasattr(data, "read"): encode = self._is_textIO(data) if encode and self.debuglevel > 0: print("encoding file using iso-8859-1") @@ -1086,6 +1098,8 @@ def send(self, data): else: raise TypeError("data should be a bytes-like object " "or an iterable, got %r" % type(data)) + else: + self._log_bytes_sent(len(data)) def _output(self, s): """Add a line of output to the current request buffer. @@ -1096,10 +1110,10 @@ def _output(self, s): def _read_readable(self, readable): if self.debuglevel > 0: - print("reading a readable") + _log.debug('sendIng a read()able') encode = self._is_textIO(readable) if encode and self.debuglevel > 0: - print("encoding file using iso-8859-1") + _log.debug('Encoding data using iso-8859-1') while datablock := readable.read(self.blocksize): if encode: datablock = datablock.encode("iso-8859-1") @@ -1114,6 +1128,8 @@ def _send_output(self, message_body=None, encode_chunked=False): self._buffer.extend((b"", b"")) msg = b"\r\n".join(self._buffer) del self._buffer[:] + _log.info('Sending %s request to %s:%s for %s', self._method.upper(), + self.host, self.port, self._url) self.send(msg) if message_body is not None: @@ -1146,7 +1162,7 @@ def _send_output(self, message_body=None, encode_chunked=False): for chunk in chunks: if not chunk: if self.debuglevel > 0: - print('Zero length chunk ignored') + _log.info('Zero length chunk ignored') continue if encode_chunked and self._http_vsn == 11: @@ -1174,7 +1190,6 @@ def putrequest(self, method, url, skip_host=False, if self.__response and self.__response.isclosed(): self.__response = None - # in certain cases, we cannot issue another request on this connection. # this occurs when: # 1) we are in the process of sending a request. (_CS_REQ_STARTED) @@ -1200,13 +1215,18 @@ def putrequest(self, method, url, skip_host=False, self._validate_method(method) + _log.debug('Preparing to send %s request to %s:%s for %s', + method.upper(), self.host, self.port, url) + # Save the method for use later in the response phase + self._method = method url = url or '/' self._validate_path(url) request = '%s %s %s' % (method, url, self._http_vsn_str) + self._url = url self._output(self._encode_request(request)) @@ -1276,11 +1296,11 @@ def putrequest(self, method, url, skip_host=False, # we can accept "chunked" Transfer-Encodings, but no others # NOTE: no TE header implies *only* "chunked" - #self.putheader('TE', 'chunked') + # self.putheader('TE', 'chunked') # if TE is supplied in the header, then it must appear in a # Connection header. - #self.putheader('Connection', 'TE') + # self.putheader('Connection', 'TE') else: # For HTTP/1.0, the server will assume "not chunked" @@ -1339,6 +1359,7 @@ def putheader(self, header, *values): if _is_illegal_header_value(values[i]): raise ValueError('Invalid header value %r' % (values[i],)) + _log.debug('Appending header: (%s: %s)', header, values) value = b'\r\n\t'.join(values) header = header + b': ' + value self._output(header) @@ -1391,7 +1412,7 @@ def _send_request(self, method, url, body, headers, encode_chunked): if content_length is None: if body is not None: if self.debuglevel > 0: - print('Unable to determine size of %r' % body) + _log.error('Unable to determine size of %r', body) encode_chunked = True self.putheader('Transfer-Encoding', 'chunked') else: @@ -1443,8 +1464,8 @@ def getresponse(self): raise ResponseNotReady(self.__state) if self.debuglevel > 0: - response = self.response_class(self.sock, self.debuglevel, - method=self._method) + response = self.response_class( + self.sock, self.debuglevel, method=self._method) else: response = self.response_class(self.sock, method=self._method) @@ -1468,10 +1489,15 @@ def getresponse(self): self.__response = response return response - except: + except Exception: response.close() raise + def _log_bytes_sent(self, bytes_sent): + _log.debug('Sent %s byte%s to %s:%s', bytes_sent, + '' if bytes_sent == 1 else 's', self.host, self.port) + + try: import ssl except ImportError: @@ -1497,6 +1523,7 @@ def __init__(self, host, port=None, def connect(self): "Connect to a host on a given (SSL) port." + _log.info('Connecting via SSL to %s:%s', self.host, self.port) super().connect() if self._tunnel_host: @@ -1509,33 +1536,41 @@ def connect(self): __all__.append("HTTPSConnection") + class HTTPException(Exception): # Subclasses that define an __init__ must call Exception.__init__ # or define self.args. Otherwise, str() will fail. pass + class NotConnected(HTTPException): pass + class InvalidURL(HTTPException): pass + class UnknownProtocol(HTTPException): def __init__(self, version): self.args = version, self.version = version + class UnknownTransferEncoding(HTTPException): pass + class UnimplementedFileMode(HTTPException): pass + class IncompleteRead(HTTPException): def __init__(self, partial, expected=None): self.args = partial, self.partial = partial self.expected = expected + def __repr__(self): if self.expected is not None: e = ', %i more expected' % self.expected @@ -1543,20 +1578,27 @@ def __repr__(self): e = '' return '%s(%i bytes read%s)' % (self.__class__.__name__, len(self.partial), e) - __str__ = object.__str__ + + def __str__(self): + return repr(self) + class ImproperConnectionState(HTTPException): pass + class CannotSendRequest(ImproperConnectionState): pass + class CannotSendHeader(ImproperConnectionState): pass + class ResponseNotReady(ImproperConnectionState): pass + class BadStatusLine(HTTPException): def __init__(self, line): if not line: @@ -1564,15 +1606,18 @@ def __init__(self, line): self.args = line, self.line = line + class LineTooLong(HTTPException): def __init__(self, line_type): HTTPException.__init__(self, "got more than %d bytes when reading %s" % (_MAXLINE, line_type)) + class RemoteDisconnected(ConnectionResetError, BadStatusLine): def __init__(self, *pos, **kw): BadStatusLine.__init__(self, "") ConnectionResetError.__init__(self, *pos, **kw) + # for backwards compatibility error = HTTPException diff --git a/Lib/test/test_httplib.py b/Lib/test/test_httplib.py index 44044d0385c72e..59febffd5ebb03 100644 --- a/Lib/test/test_httplib.py +++ b/Lib/test/test_httplib.py @@ -4,6 +4,7 @@ import io import itertools import os +import logging import array import re import socket @@ -135,6 +136,17 @@ def create_connection(self, *pos, **kw): return FakeSocket(*self.fake_socket_args) class HeaderTests(TestCase): + + def setUp(self): + self.handlers = logging.root.handlers + self.saved_handlers = logging._handlers.copy() + self.saved_handler_list = logging._handlerList[:] + + def tearDown(self): + logging._handlers.clear() + logging._handlers.update(self.saved_handlers) + logging._handlerList[:] = self.saved_handler_list + def test_auto_headers(self): # Some headers are added automatically, but should not be added by # .request() if they are explicitly set. @@ -378,13 +390,17 @@ def test_headers_debuglevel(self): ) sock = FakeSocket(body) resp = client.HTTPResponse(sock, debuglevel=1) + logging.basicConfig(level=logging.INFO) with support.captured_stdout() as output: + output_handler = logging.StreamHandler(output) + _logger = logging.getLogger('http.client') + _logger.addHandler(output_handler) resp.begin() lines = output.getvalue().splitlines() self.assertEqual(lines[0], "reply: 'HTTP/1.1 200 OK\\r\\n'") - self.assertEqual(lines[1], "header: First: val") - self.assertEqual(lines[2], "header: Second: val1") - self.assertEqual(lines[3], "header: Second: val2") + self.assertEqual(lines[1], "Received response: 200 OK") + self.assertEqual(lines[2], "Received header: ('First': 'val')") + self.assertEqual(lines[3], "Received header: ('Second': 'val1')") def test_max_response_headers(self): max_headers = client._MAXHEADERS + 20 @@ -2579,7 +2595,11 @@ def test_tunnel_debuglog(self): self.conn._create_connection = self._create_connection(response_text) self.conn.set_tunnel('destination.com') + logging.basicConfig(level=logging.INFO) with support.captured_stdout() as output: + output_handler = logging.StreamHandler(output) + _logger = logging.getLogger('http.client') + _logger.addHandler(output_handler) self.conn.request('PUT', '/', '') lines = output.getvalue().splitlines() self.assertIn('header: {}'.format(expected_header), lines) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 8815426fc99c39..b9705b4cbb6d1c 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -2167,8 +2167,6 @@ def handle_request(self, request): def test_output(self): # The log message sent to the HTTPHandler is properly received. logger = logging.getLogger("http") - root_logger = self.root_logger - root_logger.removeHandler(self.root_logger.handlers[0]) for secure in (False, True): addr = ('localhost', 0) if secure: @@ -2197,7 +2195,7 @@ def test_output(self): context=context, credentials=('foo', 'bar')) self.log_data = None - root_logger.addHandler(self.h_hdlr) + logger.addHandler(self.h_hdlr) for method in ('GET', 'POST'): self.h_hdlr.method = method @@ -2212,12 +2210,13 @@ def test_output(self): d = parse_qs(self.log_data.query) else: d = parse_qs(self.post_data.decode('utf-8')) - self.assertEqual(d['name'], ['http']) + self.assertEqual(d['name'], ['httplogger']) self.assertEqual(d['funcName'], ['test_output']) self.assertEqual(d['msg'], [msg]) self.server.stop() - self.root_logger.removeHandler(self.h_hdlr) + logger.removeHandler(self.h_hdlr) + self.h_hdlr.close() class MemoryTest(BaseTest): diff --git a/Misc/NEWS.d/next/Library/2025-12-07-00-00-00.bpo-24255.IZcKUO.rst b/Misc/NEWS.d/next/Library/2025-12-07-00-00-00.bpo-24255.IZcKUO.rst new file mode 100644 index 00000000000000..d77e5fd49fe979 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2025-12-07-00-00-00.bpo-24255.IZcKUO.rst @@ -0,0 +1 @@ +Replace debug level-related logic in http.client with Python's standard logging module. Patch by Sanyam Khurana.