Log All Requests from the Python-Requests Module

Log all requests from the python-requests module

The underlying urllib3 library logs all new connections and URLs with the logging module, but not POST bodies. For GET requests this should be enough:

import logging

logging.basicConfig(level=logging.DEBUG)

which gives you the most verbose logging option; see the logging HOWTO for more details on how to configure logging levels and destinations.

Short demo:

>>> import requests
>>> import logging
>>> logging.basicConfig(level=logging.DEBUG)
>>> r = requests.get('http://httpbin.org/get?foo=bar&baz=python')
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): httpbin.org:80
DEBUG:urllib3.connectionpool:http://httpbin.org:80 "GET /get?foo=bar&baz=python HTTP/1.1" 200 366

Depending on the exact version of urllib3, the following messages are logged:

• INFO: Redirects
• WARN: Connection pool full (if this happens often increase the connection pool size)
• WARN: Failed to parse headers (response headers with invalid format)
• WARN: Retrying the connection
• WARN: Certificate did not match expected hostname
• WARN: Received response with both Content-Length and Transfer-Encoding, when processing a chunked response
• DEBUG: New connections (HTTP or HTTPS)
• DEBUG: Dropped connections
• DEBUG: Connection details: method, path, HTTP version, status code and response length
• DEBUG: Retry count increments

This doesn't include headers or bodies. urllib3 uses the http.client.HTTPConnection class to do the grunt-work, but that class doesn't support logging, it can normally only be configured to print to stdout. However, you can rig it to send all debug information to logging instead by introducing an alternative print name into that module:

import logging
import http.client

httpclient_logger = logging.getLogger("http.client")

def httpclient_logging_patch(level=logging.DEBUG):
    """Enable HTTPConnection debug logging to the logging framework"""

    def httpclient_log(*args):
        httpclient_logger.log(level, " ".join(args))

    # mask the print() built-in in the http.client module to use
    # logging instead
    http.client.print = httpclient_log
    # enable debugging
    http.client.HTTPConnection.debuglevel = 1

Calling httpclient_logging_patch() causes http.client connections to output all debug information to a standard logger, and so are picked up by logging.basicConfig():

>>> httpclient_logging_patch()
>>> r = requests.get('http://httpbin.org/get?foo=bar&baz=python')
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): httpbin.org:80
DEBUG:http.client:send: b'GET /get?foo=bar&baz=python HTTP/1.1\r\nHost: httpbin.org\r\nUser-Agent: python-requests/2.22.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
DEBUG:http.client:reply: 'HTTP/1.1 200 OK\r\n'
DEBUG:http.client:header: Date: Tue, 04 Feb 2020 13:36:53 GMT
DEBUG:http.client:header: Content-Type: application/json
DEBUG:http.client:header: Content-Length: 366
DEBUG:http.client:header: Connection: keep-alive
DEBUG:http.client:header: Server: gunicorn/19.9.0
DEBUG:http.client:header: Access-Control-Allow-Origin: *
DEBUG:http.client:header: Access-Control-Allow-Credentials: true
DEBUG:urllib3.connectionpool:http://httpbin.org:80 "GET /get?foo=bar&baz=python HTTP/1.1" 200 366

log all http requests in python

See this answer from elsewhere on stackoverflow, if you're sure that all requests are using the requests package:

https://stackoverflow.com/a/16337639/6709958

Essentially, you just need to activate logging.

python3.7 requests: logging to a file: Does not log everything

Have you tried to monkey-patch the print function of http.client module? Unfortunately, it uses prints instead of Python logging module, hence this behaviour.

Adding add the following piece of code before your request should work:

def print_to_log(*args):
    requests_log.debug(" ".join(args)) 
http_client.print = print_to_log

Related answers (Log all requests from the python-requests module and Python HTTP request and debug level logging to the log file).

Python HTTP request and debug level logging to the log file

You are adding your handlers and level changes in the wrong place.

The Python logging module treats logger objects as existing in a hierarchy, based on their name and the presence of . delimiters in those names. The name "foo.bar.baz" for a logger is logically placed as child of foo.bar and of foo, should they exist. At the base of the hierarchy is the root logger, which has no name. You access it with logging.getLogger() (no arguments, although '' and None also would work).

Now, when logging messages, first the message has to pass the effective level of the logger. If they passed that the messages are passed to the handlers on every logger from the current logger down to the root, provided they clear the level of each handler found.

To find the effective level, the hierarchy is traversed to find the nearest logger object with a level set; if there are none then messages always pass. When traversing the hierarchy to find handlers, a log object can block propagation (propagate is set to False), at which point traversing stops.

When you are trying to handle messages for urllib3.connectionpool(), you need to put a handler on one of three locations: the logger for urllib3.connectionpool, for urllib3 or the root logger. Your code doesn't do that.

You instead set up your handlers on your own logger with a different name:

_logger = logging.getLogger(__name__)

That is guaranteed to not match the root logger (__name__ would need to be empty, that's never the case) nor the urllib3 or urllib3.connectionpool loggers (which would mean your module is also called urllib3 or urllib3.connectionpool).

Because it is not in the path that urllib3.connectionpool log messages would follow, your handlers are never going to be given those messages.

Instead, you want to configure the root logger:

fileHandler = logging.handlers.TimedRotatingFileHandler("{0}/{1}.log".format(logPath, logFileName), when="midnight")
fileHandler.setFormatter(logFormatter)
root = logging.getLogger()
root.setLevel(logging.DEBUG)
root.addHandler(fileHandler)

You could just set the log level of each handler to a log level you want to see on that handler, rather than on the root logger (or in addition to the root logger). Remember that the level set on the root logger is used to determine the effective level of other loggers in the hierarchy that don't have a level set directly and that the effective level works as a 'high water mark' for all messages. If the root logger is set to INFO, and no other handlers are configured, then your handlers will never see DEBUG messages. The default level for the root logger is WARNING.

You usually only ever want to use named loggers in your modules to produce log messages, and put all your handlers on the root. Anything else is specialised, 'advanced' use of the logger module (e.g. a dedicated, separate handler just for the urllib3 log messages, or silencing a whole package by setting their lowest-level logger object to propagate = False).

Finally, logging.basicConfig() configures the root logger too, but only if there are no handlers on the root logger already. If you use force=True then basicConfig() will remove all existing handlers, then configure the handlers on the root. It'll always create a Formatter() instance and set it on all handlers.

You could use basicConfig() for all your root logger needs:

import http.client
import logging
import os.path
import sys
from logging.handlers import TimedRotatingFileHandler

def setup_logging(loglevel):
    # the file handler receives all messages from level DEBUG on up, regardless
    fileHandler = TimedRotatingFileHandler(
        os.path.join(logPath, logFileName + ".log"),
        when="midnight"
    )
    fileHandler.setLevel(logging.DEBUG)
    handlers = [fileHandler]

    if loglevel is not None:
        # if a log level is configured, use that for logging to the console
        stream_handler = logging.StreamHandler(sys.stdout)
        stream_handler.setLevel(loglevel)
        handlers.append(stream_handler)

    if loglevel == logging.DEBUG:
        # when logging at debug level, make http.client extra chatty too
        # http.client *uses `print()` calls*, not logging.
        http.client.HTTPConnection.debuglevel = 1

    # finally, configure the root logger with our choice of handlers
    # the logging level of the root set to DEBUG (defaults to WARNING otherwise).
    logformat = "%(asctime)s [%(threadName)-12.12s] [%(levelname)-5.5s]  %(message)s"
    logging.basicConfig(
        format=logformat, datefmt="%Y-%m-%d %H:%M:%S",
        handlers=handlers, level=logging.DEBUG
    )

Side note: the http.client library does not use logging to output debug messages; it will always use print() to output those. If you want to see those messages appear in your logs, you'll need to monkey-patch the library, adding in an alternative print() global:

import http.client
import logging

http_client_logger = logging.getLogger("http.client")

def print_to_log(*args):
    http_client_logger.debug(" ".join(args)) 

# monkey-patch a `print` global into the http.client module; all calls to
# print() in that module will then use our print_to_log implementation
http.client.print = print_to_log

With the above http.client trick applied and setup_logging(logging.DEBUG), I see the following logs appear both on stdout and in the file when I use requests.get("https://stackoverflow.com/a/58769712/100297"):

2019-11-08 16:17:26 [MainThread  ] [DEBUG]  Starting new HTTPS connection (1): stackoverflow.com:443
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  send: b'GET /a/58769712/100297 HTTP/1.1\r\nHost: stackoverflow.com\r\nUser-Agent: python-requests/2.22.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  reply: 'HTTP/1.1 302 Found\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Cache-Control: private
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Type: text/html; charset=utf-8
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Location: /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712#58769712
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Frame-Options: SAMEORIGIN
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Request-Guid: 761bd2f8-3e5c-453a-ab46-d01284940541
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Strict-Transport-Security: max-age=15552000
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Feature-Policy: microphone 'none'; speaker 'none'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Security-Policy: upgrade-insecure-requests; frame-ancestors 'self' https://stackexchange.com
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Length: 214
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Date: Fri, 08 Nov 2019 16:17:27 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Via: 1.1 varnish
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Connection: keep-alive
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Served-By: cache-lhr7324-LHR
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache: MISS
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache-Hits: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Timer: S1573229847.069848,VS0,VE80
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Vary: Fastly-SSL
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-DNS-Prefetch-Control: off
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Set-Cookie: prov=0e92634f-abce-9f8e-1865-0d35ebecc595; domain=.stackoverflow.com; expires=Fri, 01-Jan-2055 00:00:00 GMT; path=/; HttpOnly
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  https://stackoverflow.com:443 "GET /a/58769712/100297 HTTP/1.1" 302 214
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  send: b'GET /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712 HTTP/1.1\r\nHost: stackoverflow.com\r\nUser-Agent: python-requests/2.22.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nCookie: prov=0e92634f-abce-9f8e-1865-0d35ebecc595\r\n\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  reply: 'HTTP/1.1 200 OK\r\n'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Cache-Control: private
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Type: text/html; charset=utf-8
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Encoding: gzip
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Last-Modified: Fri, 08 Nov 2019 16:16:07 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Frame-Options: SAMEORIGIN
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Request-Guid: 5e48399e-a91c-44aa-aad6-00a96014131f
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Strict-Transport-Security: max-age=15552000
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Feature-Policy: microphone 'none'; speaker 'none'
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Security-Policy: upgrade-insecure-requests; frame-ancestors 'self' https://stackexchange.com
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Content-Length: 42625
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Accept-Ranges: bytes
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Date: Fri, 08 Nov 2019 16:17:27 GMT
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Via: 1.1 varnish
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Age: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Connection: keep-alive
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Served-By: cache-lhr7324-LHR
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache: MISS
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Cache-Hits: 0
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-Timer: S1573229847.189349,VS0,VE95
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: Vary: Accept-Encoding,Fastly-SSL
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  header: X-DNS-Prefetch-Control: off
2019-11-08 16:17:27 [MainThread  ] [DEBUG]  https://stackoverflow.com:443 "GET /questions/58738195/python-http-request-and-debug-level-logging-to-the-log-file/58769712 HTTP/1.1" 200 42625

You can reproduce this with a file with:

import requests
import sys

logPath, logFileName = "/tmp", "demo"
level = logging.DEBUG if "-v" in sys.argv else None
setup_logging(level)

requests.get("https://stackoverflow.com/a/58769712/100297")

added in addition to the code above. You can then use python <script.py> -v to set the level to verbose and compare that to python <script.py> with the level not set at all.

How can I see the entire HTTP request that's being sent by my Python application?

A simple method: enable logging in recent versions of Requests (1.x and higher.)

Requests uses the http.client and logging module configuration to control logging verbosity, as described here.

Demonstration

Code excerpted from the linked documentation:

import requests
import logging

# These two lines enable debugging at httplib level (requests->urllib3->http.client)
# You will see the REQUEST, including HEADERS and DATA, and RESPONSE with HEADERS but without DATA.
# The only thing missing will be the response.body which is not logged.
try:
    import http.client as http_client
except ImportError:
    # Python 2
    import httplib as http_client
http_client.HTTPConnection.debuglevel = 1

# You must initialize logging, otherwise you'll not see debug output.
logging.basicConfig()
logging.getLogger().setLevel(logging.DEBUG)
requests_log = logging.getLogger("requests.packages.urllib3")
requests_log.setLevel(logging.DEBUG)
requests_log.propagate = True

requests.get('https://httpbin.org/headers')

Example Output

$ python requests-logging.py 
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): httpbin.org
send: 'GET /headers HTTP/1.1\r\nHost: httpbin.org\r\nAccept-Encoding: gzip, deflate, compress\r\nAccept: */*\r\nUser-Agent: python-requests/1.2.0 CPython/2.7.3 Linux/3.2.0-48-generic\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Content-Type: application/json
header: Date: Sat, 29 Jun 2013 11:19:34 GMT
header: Server: gunicorn/0.17.4
header: Content-Length: 226
header: Connection: keep-alive
DEBUG:requests.packages.urllib3.connectionpool:"GET /headers HTTP/1.1" 200 226

How do I disable log messages from the Requests library?

I found out how to configure requests's logging level, it's done via the standard logging module. I decided to configure it to not log messages unless they are at least warnings:

import logging

logging.getLogger("requests").setLevel(logging.WARNING)

If you wish to apply this setting for the urllib3 library (typically used by requests) too, add the following:

logging.getLogger("urllib3").setLevel(logging.WARNING)

How to get log of every retry attempt made by Python Requests Library?

You can write your own Class to add logs it should be inherited from the Retry.

class LogRetry(Retry):
  """
     Adding extra logs before making a retry request     
  """      
  def __init__(self, *args, **kwargs):
    logger.info(f'<add your logs here>')
    super().__init__(*args, **kwargs)

retries = LogRetry(<your args>)

---

Related Topics