Registrar todas as solicitações do módulo python-requests

95

Estou usando solicitações de python . Preciso depurar alguma OAuthatividade e, para isso, gostaria que ele registrasse todas as solicitações realizadas. Eu poderia obter essas informações com ngrep, mas infelizmente não é possível fazer o grep de conexões https (que são necessárias para OAuth)

Como posso ativar o registro de todos os URLs (+ parâmetros) que Requestsestá acessando?

blueFast
fonte
A resposta de @yohann mostra como obter ainda mais saída de registro, incluindo os cabeçalhos que você está enviando. Deve ser a resposta aceita, e não a de Martijn, que não mostra os cabeçalhos que você acabou recebendo por meio do WireShark e personalizando manualmente uma solicitação.
nealmcb

Respostas:

91

A urllib3biblioteca subjacente registra todas as novas conexões e URLs com o loggingmódulo , mas não os POSTcorpos. Para GETsolicitações, isso deve ser suficiente:

import logging

logging.basicConfig(level=logging.DEBUG)

que oferece a opção de registro mais detalhada; veja o registro HOWTO para mais detalhes sobre como configurar níveis de registro e destinos.

Demonstração curta:

>>> 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

Dependendo da versão exata do urllib3, as seguintes mensagens são registradas:

  • INFO: Redireciona
  • WARN: Pool de conexão cheio (se isso acontecer, aumente o tamanho do pool de conexão)
  • WARN: Falha ao analisar os cabeçalhos (cabeçalhos de resposta com formato inválido)
  • WARN: Tentando a conexão novamente
  • WARN: O certificado não corresponde ao nome de host esperado
  • WARN: Resposta recebida com Content-Length e Transfer-Encoding, ao processar uma resposta fragmentada
  • DEBUG: Novas conexões (HTTP ou HTTPS)
  • DEBUG: Conexões perdidas
  • DEBUG: Detalhes da conexão: método, caminho, versão HTTP, código de status e comprimento da resposta
  • DEBUG: Repetir incrementos de contagem

Isso não inclui cabeçalhos ou corpos. urllib3usa a http.client.HTTPConnectionclasse para fazer o trabalho pesado, mas essa classe não oferece suporte para registro, normalmente só pode ser configurada para imprimir em stdout. No entanto, você pode prepará-lo para enviar todas as informações de depuração para o registro, em vez de introduzir um printnome alternativo nesse módulo:

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

A chamada httpclient_logging_patch()faz com que as http.clientconexões enviem todas as informações de depuração para um registrador padrão e, portanto, são coletadas por 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
Martijn Pieters
fonte
2
Estranhamente, não vejo access_tokenna solicitação OAuth. O Linkedin está reclamando de uma solicitação não autorizada e quero verificar se a biblioteca que estou usando ( rauthalém requests) está enviando esse token com a solicitação. Eu esperava ver isso como um parâmetro de consulta, mas talvez esteja nos cabeçalhos de solicitação. Como posso forçar a urllib3mostrar os cabeçalhos também? E o corpo do pedido? Para simplificar: como posso ver a solicitação FULL ?
blueFast
Você não pode fazer isso sem patch, infelizmente. A maneira mais comum de diagnosticar tais problemas é com um proxy ou registrador de pacotes (eu uso o WireShark para capturar solicitações e respostas completas por conta própria). Vejo que você fez uma nova pergunta sobre o assunto.
Martijn Pieters
1
Claro, estou depurando agora com o WireShark, mas estou com um problema: se eu fizer http, vejo o conteúdo completo do pacote, mas o Linkedin retorna 401, o que é esperado, já que o Linkedin diz para usar https. Mas com https também não está funcionando, e não posso depurar, pois não posso inspecionar a camada TLS com threadshark.
blueFast
1
@nealmcb: gah, sim, definir um atributo de classe global realmente habilitaria a depuração httplib. Eu gostaria que a biblioteca fosse usada em seu logginglugar; a saída de depuração é gravada diretamente no stdout, em vez de permitir que você redirecione para um destino de log de sua escolha.
Martijn Pieters
111

Você precisa habilitar a depuração no httplibnível ( requestsurllib3httplib).

Aqui estão algumas funções para alternar ( ..._on()e ..._off()) ou ativá-lo temporariamente:

import logging
import contextlib
try:
    from http.client import HTTPConnection # py3
except ImportError:
    from httplib import HTTPConnection # py2

def debug_requests_on():
    '''Switches on logging of the requests module.'''
    HTTPConnection.debuglevel = 1

    logging.basicConfig()
    logging.getLogger().setLevel(logging.DEBUG)
    requests_log = logging.getLogger("requests.packages.urllib3")
    requests_log.setLevel(logging.DEBUG)
    requests_log.propagate = True

def debug_requests_off():
    '''Switches off logging of the requests module, might be some side-effects'''
    HTTPConnection.debuglevel = 0

    root_logger = logging.getLogger()
    root_logger.setLevel(logging.WARNING)
    root_logger.handlers = []
    requests_log = logging.getLogger("requests.packages.urllib3")
    requests_log.setLevel(logging.WARNING)
    requests_log.propagate = False

@contextlib.contextmanager
def debug_requests():
    '''Use with 'with'!'''
    debug_requests_on()
    yield
    debug_requests_off()

Uso de demonstração:

>>> requests.get('http://httpbin.org/')
<Response [200]>

>>> debug_requests_on()
>>> requests.get('http://httpbin.org/')
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): httpbin.org
DEBUG:requests.packages.urllib3.connectionpool:"GET / HTTP/1.1" 200 12150
send: 'GET / HTTP/1.1\r\nHost: httpbin.org\r\nConnection: keep-alive\r\nAccept-
Encoding: gzip, deflate\r\nAccept: */*\r\nUser-Agent: python-requests/2.11.1\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Server: nginx
...
<Response [200]>

>>> debug_requests_off()
>>> requests.get('http://httpbin.org/')
<Response [200]>

>>> with debug_requests():
...     requests.get('http://httpbin.org/')
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): httpbin.org
...
<Response [200]>

Você verá REQUEST, incluindo HEADERS e DATA, e RESPONSE com HEADERS, mas sem DATA. A única coisa que falta é a resposta.body que não está registrada.

Fonte

Yohann
fonte
Obrigado pelo insight sobre como usar httplib.HTTPConnection.debuglevel = 1para obter os cabeçalhos - excelente! Mas acho que obtenho os mesmos resultados usando apenas logging.basicConfig(level=logging.DEBUG)no lugar de suas outras 5 linhas. Estou esquecendo de algo? Acho que pode ser uma maneira de definir diferentes níveis de registro para a raiz e para o urllib3, se desejar.
nealmcb
Você não tem o cabeçalho com sua solução.
Yohann
7
httplib.HTTPConnection.debuglevel = 2permitirá a impressão do corpo do POST também.
Mandible79,
1
httplib.HTTPConnection.debuglevel = 1é suficiente @ Mandible79 $ curl https://raw.githubusercontent.com/python/cpython/master/Lib/http/client.py |grep debuglevelé sempredebuglevel > 0
Yohann
3
De alguma forma para evitar que o conteúdo registrado seja enviado para a saída padrão?
yucer
45

Para aqueles que usam python 3+

import requests
import logging
import http.client

http.client.HTTPConnection.debuglevel = 1

logging.basicConfig()
logging.getLogger().setLevel(logging.DEBUG)
requests_log = logging.getLogger("requests.packages.urllib3")
requests_log.setLevel(logging.DEBUG)
requests_log.propagate = True
Forrestj
fonte
Como faço para que funcione com o arquivo de log? Parece funcionar apenas para stdout. Exemplo de problema aqui: stackoverflow.com/q/58738195/1090360
JackTheKnife
15

Ao tentar fazer com que o sistema de registro Python ( import logging) emita mensagens de registro de depuração de baixo nível, fiquei surpreso ao descobrir que:

requests --> urllib3 --> http.client.HTTPConnection

que urllib3usa apenas o loggingsistema Python :

  • requests não
  • http.client.HTTPConnection não
  • urllib3 sim

Claro, você pode extrair mensagens de depuração HTTPConnectiondefinindo:

HTTPConnection.debuglevel = 1

mas essas saídas são simplesmente emitidas por meio da printinstrução. Para provar isso, simplesmente execute um grep no client.pycódigo-fonte do Python 3.7 e veja você mesmo as instruções de impressão (obrigado @Yohann):

curl https://raw.githubusercontent.com/python/cpython/3.7/Lib/http/client.py |grep -A1 debuglevel` 

Presumivelmente, redirecionar o stdout de alguma forma pode funcionar para colocar o stdout no sistema de registro e potencialmente capturar, por exemplo, um arquivo de registro.

Escolha o ' urllib3' logger not 'requests.packages.urllib3 '

Para capturar urllib3informações de depuração por meio do loggingsistema Python 3 , ao contrário de muitos conselhos na Internet, e como @MikeSmith aponta, você não terá muita sorte em interceptar:

log = logging.getLogger('requests.packages.urllib3')

em vez disso, você precisa:

log = logging.getLogger('urllib3')

Depurando urllib3 para um arquivo de log

Aqui está um código que registra o urllib3funcionamento em um arquivo de registro usando o loggingsistema Python :

import requests
import logging
from http.client import HTTPConnection  # py3

# log = logging.getLogger('requests.packages.urllib3')  # useless
log = logging.getLogger('urllib3')  # works

log.setLevel(logging.DEBUG)  # needed
fh = logging.FileHandler("requests.log")
log.addHandler(fh)

requests.get('http://httpbin.org/')

o resultado:

Starting new HTTP connection (1): httpbin.org:80
http://httpbin.org:80 "GET / HTTP/1.1" 200 3168

Habilitando o HTTPConnection.debuglevel instruções print ()

Se você definir HTTPConnection.debuglevel = 1

from http.client import HTTPConnection  # py3
HTTPConnection.debuglevel = 1
requests.get('http://httpbin.org/')

você obterá a saída do extrato de impressão de informações adicionais de baixo nível:

send: b'GET / 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'
reply: 'HTTP/1.1 200 OK\r\n'
header: Access-Control-Allow-Credentials header: Access-Control-Allow-Origin 
header: Content-Encoding header: Content-Type header: Date header: ...

Lembre-se de que esta saída usa printe não o loggingsistema Python e, portanto, não pode ser capturada usando um loggingfluxo tradicional ou gerenciador de arquivos (embora seja possível capturar a saída para um arquivo redirecionando stdout) .

Combine os dois acima - maximize todos os registros possíveis para o console

Para maximizar todos os registros possíveis, você deve se contentar com a saída do console / stdout com isto:

import requests
import logging
from http.client import HTTPConnection  # py3

log = logging.getLogger('urllib3')
log.setLevel(logging.DEBUG)

# logging from urllib3 to console
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
log.addHandler(ch)

# print statements from `http.client.HTTPConnection` to console/stdout
HTTPConnection.debuglevel = 1

requests.get('http://httpbin.org/')

dando toda a gama de produção:

Starting new HTTP connection (1): httpbin.org:80
send: b'GET / 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'
reply: 'HTTP/1.1 200 OK\r\n'
http://httpbin.org:80 "GET / HTTP/1.1" 200 3168
header: Access-Control-Allow-Credentials header: Access-Control-Allow-Origin 
header: Content-Encoding header: ...
Abulka
fonte
3
E que tal redirecionar os detalhes de impressão para o logger?
yucer
yucer conseguiu obter os detalhes de impressão para o logger?
Erika Dsouza
3

Estou usando o python 3.4, solicitações 2.19.1:

'urllib3' é o registrador a ser obtido agora (não mais 'requests.packages.urllib3'). O registro básico ainda acontecerá sem configurar http.client.HTTPConnection.debuglevel

Mike Smith
fonte
Seria muito melhor se você explicasse mais
Jamie Lindsey
2

Tendo um script ou mesmo um subsistema de uma aplicação para depuração de protocolo de rede, é desejável ver quais são exatamente os pares solicitação-resposta, incluindo URLs efetivos, cabeçalhos, cargas úteis e o status. E normalmente não é prático instrumentar solicitações individuais em todos os lugares. Ao mesmo tempo, há considerações de desempenho que sugerem o uso de um único (ou poucos especializados) requests.Session, portanto, o seguinte pressupõe que a sugestão seja seguida.

requestssuporta os chamados ganchos de evento (a partir de 2.23, na verdade, só há responseganchos). É basicamente um ouvinte de evento e o evento é emitido antes de retornar o controle de requests.request. Neste momento, a solicitação e a resposta estão totalmente definidas, portanto, podem ser registradas.

import logging

import requests


logger = logging.getLogger('httplogger')

def logRoundtrip(response, *args, **kwargs):
    extra = {'req': response.request, 'res': response}
    logger.debug('HTTP roundtrip', extra=extra)

session = requests.Session()
session.hooks['response'].append(logRoundtrip)

É basicamente assim que registrar todas as viagens de ida e volta HTTP de uma sessão.

Formatando registros de log de ida e volta de HTTP

Para que o registro acima seja útil, pode haver um formatador de registro especializado que entende reqe resextras nos registros de registro. Pode ser assim:

import textwrap

class HttpFormatter(logging.Formatter):   

    def _formatHeaders(self, d):
        return '\n'.join(f'{k}: {v}' for k, v in d.items())

    def formatMessage(self, record):
        result = super().formatMessage(record)
        if record.name == 'httplogger':
            result += textwrap.dedent('''
                ---------------- request ----------------
                {req.method} {req.url}
                {reqhdrs}

                {req.body}
                ---------------- response ----------------
                {res.status_code} {res.reason} {res.url}
                {reshdrs}

                {res.text}
            ''').format(
                req=record.req,
                res=record.res,
                reqhdrs=self._formatHeaders(record.req.headers),
                reshdrs=self._formatHeaders(record.res.headers),
            )

        return result

formatter = HttpFormatter('{asctime} {levelname} {name} {message}', style='{')
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logging.basicConfig(level=logging.DEBUG, handlers=[handler])

Agora, se você fizer algumas solicitações usando o session, como:

session.get('https://httpbin.org/user-agent')
session.get('https://httpbin.org/status/200')

A saída para stderrserá a seguinte.

2020-05-14 22:10:13,224 DEBUG urllib3.connectionpool Starting new HTTPS connection (1): httpbin.org:443
2020-05-14 22:10:13,695 DEBUG urllib3.connectionpool https://httpbin.org:443 "GET /user-agent HTTP/1.1" 200 45
2020-05-14 22:10:13,698 DEBUG httplogger HTTP roundtrip
---------------- request ----------------
GET https://httpbin.org/user-agent
User-Agent: python-requests/2.23.0
Accept-Encoding: gzip, deflate
Accept: */*
Connection: keep-alive

None
---------------- response ----------------
200 OK https://httpbin.org/user-agent
Date: Thu, 14 May 2020 20:10:13 GMT
Content-Type: application/json
Content-Length: 45
Connection: keep-alive
Server: gunicorn/19.9.0
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true

{
  "user-agent": "python-requests/2.23.0"
}


2020-05-14 22:10:13,814 DEBUG urllib3.connectionpool https://httpbin.org:443 "GET /status/200 HTTP/1.1" 200 0
2020-05-14 22:10:13,818 DEBUG httplogger HTTP roundtrip
---------------- request ----------------
GET https://httpbin.org/status/200
User-Agent: python-requests/2.23.0
Accept-Encoding: gzip, deflate
Accept: */*
Connection: keep-alive

None
---------------- response ----------------
200 OK https://httpbin.org/status/200
Date: Thu, 14 May 2020 20:10:13 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 0
Connection: keep-alive
Server: gunicorn/19.9.0
Access-Control-Allow-Origin: *
Access-Control-Allow-Credentials: true

Uma maneira de GUI

Quando você tem muitas consultas, ter uma IU simples e uma maneira de filtrar registros é útil. Vou mostrar como usar o Chronologer para isso (do qual sou o autor).

Primeiro, o gancho foi reescrito para produzir registros que loggingpodem ser serializados durante o envio por fio. Pode ser assim:

def logRoundtrip(response, *args, **kwargs): 
    extra = {
        'req': {
            'method': response.request.method,
            'url': response.request.url,
            'headers': response.request.headers,
            'body': response.request.body,
        }, 
        'res': {
            'code': response.status_code,
            'reason': response.reason,
            'url': response.url,
            'headers': response.headers,
            'body': response.text
        },
    }
    logger.debug('HTTP roundtrip', extra=extra)

session = requests.Session()
session.hooks['response'].append(logRoundtrip)

Em segundo lugar, a configuração de registro deve ser adaptada para uso logging.handlers.HTTPHandler(o que o Chronologer entende).

import logging.handlers

chrono = logging.handlers.HTTPHandler(
  'localhost:8080', '/api/v1/record', 'POST', credentials=('logger', ''))
handlers = [logging.StreamHandler(), chrono]
logging.basicConfig(level=logging.DEBUG, handlers=handlers)

Finalmente, execute a instância do Chronologer. por exemplo, usando Docker:

docker run --rm -it -p 8080:8080 -v /tmp/db \
    -e CHRONOLOGER_STORAGE_DSN=sqlite:////tmp/db/chrono.sqlite \
    -e CHRONOLOGER_SECRET=example \
    -e CHRONOLOGER_ROLES="basic-reader query-reader writer" \
    saaj/chronologer \
    python -m chronologer -e production serve -u www-data -g www-data -m

E execute as solicitações novamente:

session.get('https://httpbin.org/user-agent')
session.get('https://httpbin.org/status/200')

O gerenciador de fluxo produzirá:

DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): httpbin.org:443
DEBUG:urllib3.connectionpool:https://httpbin.org:443 "GET /user-agent HTTP/1.1" 200 45
DEBUG:httplogger:HTTP roundtrip
DEBUG:urllib3.connectionpool:https://httpbin.org:443 "GET /status/200 HTTP/1.1" 200 0
DEBUG:httplogger:HTTP roundtrip

Agora, se você abrir http: // localhost: 8080 / (use "logger" para nome de usuário e senha vazia para o pop-up de autenticação básica) e clicar no botão "Abrir", você verá algo como:

Captura de tela do Chronologer

saaj
fonte