Better Debug Logging for The Python Requests Library

The requests library is the most popular python library for sending HTTP requests. As a normal part of RESTful application development you'll often want to see exactly what you're sending to the server including request headers and payload. In fact, this is especially true when you'll be communicating with an API endpoints that:

May be out of your control and sensitive to specific header values, and
Are only available over HTTPS which makes side-channel observation unavailable

Further, you'll often want to log these details in your normal application log file to be able to sift through after and find the specific request you are working with.

Unfortunately the method to turn on such debugging is a bit awkward since the requests library relies on the http.client.HTTPConnection class which do not use python's standard logging library.

This article covers the steps necessary to turn on HTTPConnection debug logging and redirect the output to your application's log file.

Step 1: Set up environment

$ python3 -m venv venv
$ . venv/bin/activate
(venv) $ pip3 install Flask requests

Step 2: Setting up the dummy test server

In order to test our app, we'll use flask to spin up a small HTTP server to accept both GET and POST requests and simply respond with 200 OK.

# test_server.py
from flask import Flask

app = Flask(__name__)


@app.route('/test', methods=['GET', 'POST'])
def test():
    return 'OK', 200

Start up the test server:

$ env FLASK_APP=test_server flask run
 * Serving Flask app "test_server"
 * Environment: production
   WARNING: This is a development server. Do not use it in a production deployment.
   Use a production WSGI server instead.
 * Debug mode: off
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)

Step 3: Initial App

Here is our minimal app that we'll add onto later:

import requests
import logging

# Set up logging to a file
logging.basicConfig(filename="app.log", level=logging.DEBUG)
logger = logging.getLogger(__name__)

url = "http://localhost:5000/test"

logger.info("Sending HTTP GET")
resp = requests.get(url)

logger.info("Sending HTTP POST")
resp = requests.post(url, data='My Test Data')

Step 4: Enabling Low-Level HTTPConnection Debugging

As mentioned above, the requests library relies on the low-level http.client.HTTPConnection class, so the first step is to enable that class's debugging functionality.

Adding the following turns on global debugging in the HTTPConnection class:

http.client.HTTPConnection.debuglevel = 1

These debug messages will be printed to the console, in order to save them to the log we will need to redirect them.

Step 5: Redirecting Console Debug Messages To A File

The next step is to monkey patch the http.client's print() function with our own that redirects the messages to a pre-defined logger instance.

def print_to_log(*args):
    logger.debug(" ".join(args))
http.client.print = print_to_log

Putting It All Together

import http
import logging
import requests

# Set up logging to a file
logging.basicConfig(filename="app.log", level=logging.DEBUG)
logger = logging.getLogger(__name__)

# Turn on global debugging for the HTTPConnection class, doing so will 
# cause debug messages to be printed to STDOUT
http.client.HTTPConnection.debuglevel = 1

# Monkey patch the print() function and redirect it to a
# logger.debug() call
def print_to_log(*args):
    logger.debug(" ".join(args))
http.client.print = print_to_log



# Test HTTP GET and POST
url = "http://localhost:5000/test"

logger.info("Sending HTTP GET")
resp = requests.get(url)

logger.info("Sending HTTP POST")
resp = requests.post(url, data='My Test Data')

Demo Output (app.log)

INFO:__main__:Sending HTTP GET
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:5000
DEBUG:__main__:send: b'GET /test HTTP/1.1\r\nHost: localhost:5000\r\nUser-Agent: python-requests/2.25.1\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\n\r\n'
DEBUG:__main__:reply: 'HTTP/1.0 200 OK\r\n'
DEBUG:__main__:header: Content-Type: text/html; charset=utf-8
DEBUG:__main__:header: Content-Length: 2
DEBUG:__main__:header: Server: Werkzeug/1.0.1 Python/3.7.3
DEBUG:__main__:header: Date: Sun, 21 Feb 2021 19:35:24 GMT
DEBUG:urllib3.connectionpool:http://localhost:5000 "GET /test HTTP/1.1" 200 2

INFO:__main__:Sending HTTP POST
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:5000
DEBUG:__main__:send: b'POST /test HTTP/1.1\r\nHost: localhost:5000\r\nUser-Agent: python-requests/2.25.1\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Length: 12\r\n\r\n'
DEBUG:__main__:send: b'My Test Data'
DEBUG:__main__:reply: 'HTTP/1.0 200 OK\r\n'
DEBUG:__main__:header: Content-Type: text/html; charset=utf-8
DEBUG:__main__:header: Content-Length: 2
DEBUG:__main__:header: Server: Werkzeug/1.0.1 Python/3.7.3
DEBUG:__main__:header: Date: Sun, 21 Feb 2021 19:35:24 GMT
DEBUG:urllib3.connectionpool:http://localhost:5000 "POST /test HTTP/1.1" 200 2