Debugging requests

I’m writing an ansible-module using ‘requests’ library. It’s nice to use and I like it, but the problem is that I can’t see the body of the stuff I send. SSL adds ‘no tcpdump’ restriction.

I’ve decide to waste some of my personal weekend time on this issue, as I feel I’m lacking the essential productivity tool in my belt.

Goal: to be able to see all details of all requests I’ve send inside some data structure. I can’t use stdout, I can’t use stderr, I can’t use logger or files. This is due to ‘ansible-module’ nature.

(random intermission: I’ve just tried to kill python2 from yet another of my machines. I was able to remove python2, but not all python(2) libraries. Some are dependencies of important software — f.e. removal of python-pip-whl breaks virtualenv package).

requests-debugger

Before diving into the depth of logger and requests modules, I found something interesting: requests-debugger

I checked my apt repo, and I start seeing things.

• python3-requests-mock — oh, thank you, 95% chance I’ll need it.
• python3-requests-cache — hm…

Unfortunately, there is no requests-debugger packaged. So, let’s switch to pip.

>>> requests.post('https://ya.ru', params={'test1':True}, data={'a':1})
<stdin> Line: 1
  2020-08-30 12:37:58 - POST: https://ya.ru ([], {'params': {'test1': True}, 'data': {'a': 1}}) {}
<Response [403]>

Em… Nice, but not the thing I want in two ways. 1. Output is on stderr (I don’t have one) 2. It’s not the real http stuff. I want to see something close to curl debug output.

More docs:

>>> requests_debugger.set(output_format=requests_debugger.CURL, max_depth=0)
>>> requests.post('https://ya.ru', params={'test1':True}, data={'a':1})
curl -i -X POST   -d '{"a": 1}' 'https://ya.ru?test1=True'

Good! Almost as good as I need. Do they have curl OUTPUT style? But curl style arguments is good, as I can just repost the request to see it by myself.

Docs are ends there, so I went to source code and found most of the things I want to have — the way they configure logger inside requests.

It does not answer my question on ‘capture’.

logging

I hate this module. It’s just so complicated most of the time. But now it may be the time it’s complexity pays out. And I need to soak in those long docs for long enough.

Let’s me rephrase my goal: I want logger to log into some python structure.

After I peeked into requests_debugger code, I found they just patch all methods for requests, there is no magic from requests itself. At the same time this answer gives me something more interesting — own ability of lower level library to perform logging. I thing I should go this way.

Again, only after I learned how to log to objects.

I found dictConfig option, which may make my life less miserable.

And this example (which calling external binary) is the thing I need. I looks like I can evade learning all details about logger again.

First try

import logging
  
LOG = []
class ListLoggerHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        global LOG
        LOG.append(msg)
list_logging_handler = ListLoggerHandler()
root = logging.getLogger()
root.addHandler(list_logging_handler)
root.setLevel(logging.DEBUG)
import requests
import pprint
requests.post('http://ya.ru', params={'a': True}, data={'dict': 1})
print("**LOG CONTENT**")
pprint.pprint(LOG)

Output:

**LOG CONTENT**
['Starting new HTTP connection (1): ya.ru:80',
 'http://ya.ru:80 "POST /?a=True HTTP/1.1" 403 None']

It’s almost as perfect as I wish it to be. The single thing I miss here is the body.

That (one I’ve talked) SO answer is a base for my updated version:

Second attempt

import logging
import http.client
LOG = []
class ListLoggerHandler(logging.Handler):
    def emit(self, record):
        msg = self.format(record)
        global LOG
        LOG.append(msg)
def httpclient_log_func(*args):
    LOG.append(args)
list_logging_handler = ListLoggerHandler()
root = logging.getLogger()
root.addHandler(list_logging_handler)
root.setLevel(logging.DEBUG)
http.client.HTTPConnection.debuglevel = 1
http.client.print = httpclient_log_func
import requests
import pprint
requests.post('http://ya.ru', params={'a': True}, data={'dict': 1})
print("**LOG CONTENT**")
pprint.pprint(LOG)

Output IS the thing I want to see:

**LOG CONTENT**
['Starting new HTTP connection (1): ya.ru:80',
 ('send:',
  "b'POST /?a=True HTTP/1.1\\r\\nHost: ya.ru\\r\\nUser-Agent: "
  'python-requests/2.22.0\\r\\nAccept-Encoding: gzip, deflate\\r\\nAccept: '
  '*/*\\r\\nConnection: keep-alive\\r\\nContent-Length: 6\\r\\nContent-Type: '
  "application/x-www-form-urlencoded\\r\\n\\r\\n'"),
 ('send:', "b'dict=1'"),
 ('reply:', "'HTTP/1.1 403 Forbidden\\r\\n'"),
 ('header:', 'Content-Encoding:', 'gzip'),
 ('header:', 'Content-Type:', 'text/html; charset=utf-8'),
 ('header:', 'Date:', 'Sun, 30 Aug 2020 10:31:35 GMT'),
 ('header:', 'ETag:', 'W/"5f469240-3077"'),
 ('header:', 'Transfer-Encoding:', 'chunked'),
 ('header:', 'X-Content-Type-Options:', 'nosniff'),
 'http://ya.ru:80 "POST /?a=True HTTP/1.1" 403 None']

All I have to do is to make it into Ansible module-specific way to pass data.

My idea is to use log variable for returning log from the module back to controller.

Return value become something like this:

...
return {
    'failed': True,
    'log': prep_log(LOG)
} 

Of course I need to be sure not to ship debugging of such scale in production module (tokens and other secrets are badly exposed), but for my own debugging it’s just a bliss.