exporting patch: # HG changeset patch # User Eryn Wells # Date 1433696891 25200 # Sun Jun 07 10:08:11 2015 -0700 # Node ID e227b1238b6519c07231e5a1134ea51bd2166b32 # Parent 0fadf332f0d4a579f84abeb666c290cd7fb2b874 Logging for http.client diff -r 0fadf332f0d4 -r e227b1238b65 Lib/http/client.py --- a/Lib/http/client.py Fri Jun 05 21:03:52 2015 -0500 +++ b/Lib/http/client.py Sun Jun 07 10:08:11 2015 -0700 @@ -72,6 +72,7 @@ import email.message import http import io +import logging import os import re import socket @@ -146,6 +147,9 @@ _METHODS_EXPECTING_BODY = {'PATCH', 'POST', 'PUT'} +_log = logging.getLogger(__name__) + + class HTTPMessage(email.message.Message): # XXX The only usage of this method is in # http.server.CGIHTTPRequestHandler. Maybe move the code there so @@ -243,8 +247,6 @@ 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)) if not line: # Presumably, the server closed the connection before # sending a valid response. @@ -270,6 +272,7 @@ raise BadStatusLine(line) except ValueError: raise BadStatusLine(line) + _log.info('Received response: %s %s', status, reason.strip()) return version, status, reason def begin(self): @@ -290,8 +293,6 @@ skip = skip.strip() if not skip: break - if self.debuglevel > 0: - print("header:", skip) self.code = self.status = status self.reason = reason.strip() @@ -305,9 +306,9 @@ self.headers = self.msg = parse_headers(self.fp) - if self.debuglevel > 0: + if _log.isEnabledFor(logging.DEBUG): for hdr in self.headers: - print("header:", hdr, end=" ") + _log.debug("Received header: ('%s': '%s')", hdr, self.headers[hdr]) # are we using the chunked-style of transfer encoding? tr_enc = self.headers.get("transfer-encoding") @@ -325,7 +326,7 @@ self.length = None length = self.headers.get("content-length") - # are we using the chunked-style of transfer encoding? + # are we using the chunked-style of transfer encoding? tr_enc = self.headers.get("transfer-encoding") if length and not self.chunked: try: @@ -449,6 +450,7 @@ raise self.length = 0 self._close_conn() # we read everything + self._log_bytes_read(len(s)) return s def readinto(self, b): @@ -479,6 +481,7 @@ self.length -= n if not self.length: self._close_conn() + self._log_bytes_read(n) return n def _read_next_chunk_size(self): @@ -545,6 +548,11 @@ break value.append(self._safe_read(chunk_left)) self.chunk_left = 0 + if _log.isEnabledFor(logging.DEBUG): + total_read = 0 + for chunk in value: + total_read += len(chunk) + self._log_bytes_read(total_read) return b''.join(value) except IncompleteRead: raise IncompleteRead(b''.join(value)) @@ -557,11 +565,13 @@ 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] @@ -569,7 +579,6 @@ mvb = mvb[n:] total_bytes += n self.chunk_left = 0 - except IncompleteRead: raise IncompleteRead(bytes(b[0:total_bytes])) @@ -713,6 +722,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') + class HTTPConnection: _http_vsn = 11 @@ -732,6 +745,7 @@ self.__response = None self.__state = _CS_IDLE self._method = None + self._url = None self._tunnel_host = None self._tunnel_port = None self._tunnel_headers = {} @@ -790,6 +804,8 @@ self.debuglevel = level def _tunnel(self): + _log.info('Tunneling through %s:%s', self._tunnel_host, self._tunnel_port) + connect_str = "CONNECT %s:%d HTTP/1.0\r\n" % (self._tunnel_host, self._tunnel_port) connect_bytes = connect_str.encode("ascii") @@ -807,6 +823,9 @@ self.close() raise OSError("Tunnel connection failed: %d %s" % (code, message.strip())) + _log.debug('Connection to tunnel host %s:%s succeeded', + self._tunnel_host, + self._tunnel_port) while True: line = response.fp.readline(_MAXLINE + 1) if len(line) > _MAXLINE: @@ -817,11 +836,10 @@ if line in (b'\r\n', b'\n', b''): break - if self.debuglevel > 0: - print('header:', line.decode()) - def connect(self): """Connect to the host and port specified in __init__.""" + _log.debug('Opening socket to %s:%s', self.host, self.port) + self.sock = self._create_connection( (self.host,self.port), self.timeout, self.source_address) self.sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) @@ -842,6 +860,7 @@ 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. @@ -855,12 +874,8 @@ else: raise NotConnected() - if self.debuglevel > 0: - print("send:", repr(data)) blocksize = 8192 - if hasattr(data, "read") : - if self.debuglevel > 0: - print("sendIng a read()able") + if hasattr(data, "read"): encode = False try: mode = data.mode @@ -871,16 +886,19 @@ else: if "b" not in mode: encode = True - if self.debuglevel > 0: - print("encoding file using iso-8859-1") - while 1: + _log.debug('Encoding data using iso-8859-1') + total_bytes_sent = 0 + while True: datablock = data.read(blocksize) if not datablock: break if encode: datablock = datablock.encode("iso-8859-1") + total_bytes_sent += len(datablock) self.sock.sendall(datablock) + self._log_bytes_sent(len(data)) return + try: self.sock.sendall(data) except TypeError: @@ -890,6 +908,8 @@ 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. @@ -908,6 +928,9 @@ 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: self.send(message_body) @@ -926,7 +949,6 @@ 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) @@ -950,11 +972,15 @@ else: raise CannotSendRequest(self.__state) + _log.debug('Preparing to send %s request to %s:%s for %s', + method.upper(), self.host, self.port, url) + # Save the method we use, we need it later in the response phase self._method = method if not url: url = '/' request = '%s %s %s' % (method, url, self._http_vsn_str) + self._url = url # Non-ASCII characters should have been eliminated earlier self._output(request.encode('ascii')) @@ -1059,8 +1085,10 @@ 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) def endheaders(self, message_body=None): @@ -1101,7 +1129,7 @@ thelen = str(os.fstat(body.fileno()).st_size) except (AttributeError, OSError): # Don't send a length if this failed - if self.debuglevel > 0: print("Cannot stat!!") + _log.error('Cannot stat: %s', body.name) if thelen is not None: self.putheader('Content-Length', thelen) @@ -1163,11 +1191,7 @@ if self.__state != _CS_REQ_SENT or self.__response: raise ResponseNotReady(self.__state) - if self.debuglevel > 0: - response = self.response_class(self.sock, self.debuglevel, - method=self._method) - else: - response = self.response_class(self.sock, method=self._method) + response = self.response_class(self.sock, method=self._method) try: try: @@ -1190,6 +1214,10 @@ 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: @@ -1225,7 +1253,7 @@ 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: