{"id":1478,"date":"2021-02-21T21:15:23","date_gmt":"2021-02-22T02:15:23","guid":{"rendered":"https:\/\/bhoey.com\/blog\/?p=1478"},"modified":"2021-02-21T21:15:24","modified_gmt":"2021-02-22T02:15:24","slug":"better-debug-logging-for-the-python-requests-library","status":"publish","type":"post","link":"https:\/\/bhoey.com\/blog\/better-debug-logging-for-the-python-requests-library\/","title":{"rendered":"Better Debug Logging for The Python Requests Library"},"content":{"rendered":"

The requests library<\/a> 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:<\/p>\n

    \n
  1. May be out of your control and sensitive to specific header values, and<\/li>\n
  2. Are only available over HTTPS which makes side-channel observation unavailable<\/li>\n<\/ol>\n

    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.<\/p>\n

    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.<\/p>\n

    This article covers the steps necessary to turn on HTTPConnection debug logging and redirect the output to your application's log file.<\/p>\n

    Step 1: Set up environment<\/h3>\n
    $ python3 -m venv venv\n$ . venv\/bin\/activate\n(venv) $ pip3 install Flask requests\n<\/pre>\n
    Step 2: Setting up the dummy test server<\/h3>\n
    In order to test our app, we'll use flask<\/a> to spin up a small HTTP server to accept both GET and POST requests and simply respond with 200 OK.<\/p>\n
    # test_server.py\nfrom flask import Flask\n\napp = Flask(__name__)\n\n\n@app.route('\/test', methods=['GET', 'POST'])\ndef test():\n    return 'OK', 200\n<\/pre>\n
    Start up the test server:<\/p>\n
    $ env FLASK_APP=test_server flask run\n * Serving Flask app \"test_server\"\n * Environment: production\n   WARNING: This is a development server. Do not use it in a production deployment.\n   Use a production WSGI server instead.\n * Debug mode: off\n * Running on http:\/\/127.0.0.1:5000\/ (Press CTRL+C to quit)\n<\/pre>\n
    Step 3: Initial App<\/h3>\n
    Here is our minimal app that we'll add onto later:<\/p>\n
    import requests\nimport logging\n\n# Set up logging to a file\nlogging.basicConfig(filename=\"app.log\", level=logging.DEBUG)\nlogger = logging.getLogger(__name__)\n\nurl = \"http:\/\/localhost:5000\/test\"\n\nlogger.info(\"Sending HTTP GET\")\nresp = requests.get(url)\n\nlogger.info(\"Sending HTTP POST\")\nresp = requests.post(url, data='My Test Data')\n<\/pre>\n
    Step 4: Enabling Low-Level HTTPConnection Debugging<\/h3>\n
    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.<\/p>\n
    Adding the following turns on global debugging in the HTTPConnection class:<\/p>\n
    http.client.HTTPConnection.debuglevel = 1\n<\/pre>\n
    These debug messages will be printed to the console, in order to save them to the log we will need to redirect them.<\/p>\n
    Step 5: Redirecting Console Debug Messages To A File<\/h3>\n
    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.<\/p>\n
    def print_to_log(*args):\n    logger.debug(\" \".join(args))\nhttp.client.print = print_to_log\n<\/pre>\n
    Putting It All Together<\/h3>\n
    import http\nimport logging\nimport requests\n\n# Set up logging to a file\nlogging.basicConfig(filename=\"app.log\", level=logging.DEBUG)\nlogger = logging.getLogger(__name__)\n\n# Turn on global debugging for the HTTPConnection class, doing so will \n# cause debug messages to be printed to STDOUT\nhttp.client.HTTPConnection.debuglevel = 1\n\n# Monkey patch the print() function and redirect it to a\n# logger.debug() call\ndef print_to_log(*args):\n    logger.debug(\" \".join(args))\nhttp.client.print = print_to_log\n\n\n\n# Test HTTP GET and POST\nurl = \"http:\/\/localhost:5000\/test\"\n\nlogger.info(\"Sending HTTP GET\")\nresp = requests.get(url)\n\nlogger.info(\"Sending HTTP POST\")\nresp = requests.post(url, data='My Test Data')\n<\/pre>\n
    Demo Output (app.log)<\/h3>\n
    INFO:__main__:Sending HTTP GET\nDEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:5000\nDEBUG:__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'\nDEBUG:__main__:reply: 'HTTP\/1.0 200 OK\\r\\n'\nDEBUG:__main__:header: Content-Type: text\/html; charset=utf-8\nDEBUG:__main__:header: Content-Length: 2\nDEBUG:__main__:header: Server: Werkzeug\/1.0.1 Python\/3.7.3\nDEBUG:__main__:header: Date: Sun, 21 Feb 2021 19:35:24 GMT\nDEBUG:urllib3.connectionpool:http:\/\/localhost:5000 \"GET \/test HTTP\/1.1\" 200 2\n<\/pre>\n
    INFO:__main__:Sending HTTP POST\nDEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:5000\nDEBUG:__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'\nDEBUG:__main__:send: b'My Test Data'\nDEBUG:__main__:reply: 'HTTP\/1.0 200 OK\\r\\n'\nDEBUG:__main__:header: Content-Type: text\/html; charset=utf-8\nDEBUG:__main__:header: Content-Length: 2\nDEBUG:__main__:header: Server: Werkzeug\/1.0.1 Python\/3.7.3\nDEBUG:__main__:header: Date: Sun, 21 Feb 2021 19:35:24 GMT\nDEBUG:urllib3.connectionpool:http:\/\/localhost:5000 \"POST \/test HTTP\/1.1\" 200 2\n<\/pre>\n","protected":false},"excerpt":{"rendered":"
    The requests library<\/a> 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. [Continue reading...] Better Debug Logging for The Python Requests Library<\/span><\/a><\/p>\n","protected":false},"author":2,"featured_media":1532,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":[],"categories":[75,23,51],"tags":[98,97,85,96],"_links":{"self":[{"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/posts\/1478"}],"collection":[{"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/comments?post=1478"}],"version-history":[{"count":53,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/posts\/1478\/revisions"}],"predecessor-version":[{"id":1540,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/posts\/1478\/revisions\/1540"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/media\/1532"}],"wp:attachment":[{"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/media?parent=1478"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/categories?post=1478"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/bhoey.com\/blog\/wp-json\/wp\/v2\/tags?post=1478"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}