logging of raw request/response

[remdragon]

Is your feature request related to a problem?

I have scenarios where I need to be able to see the raw request/response for a given HTTP interaction. For example, I'm currently getting a 401 unauthorized back from Twilio, and I need to see the raw request/response to diagnose why it's failing because I know the credentials are correct (I know this because I had to convert some lua code to python and the code and credentials were working without a problem in lua).

This is also useful when trying to prove to an API vendor that they're doing something wrong like sending an html content-type but the content itself is obviously json, etc.

Describe the solution you'd like

I'd like a simple, clean, supported way to opt-in to raw logging of requests/responses. This would probably be cleanest by allowing an optional logging callback in ClientSession's init() as well as the individual request methods, for example:

async with aiohttp.ClientSession( rawlog = lambda s: log.debug( s )) as session:
    ...

or if I didn't want session-wide logging:

async with aiohttp.ClientSession() as session:
    async with session.get( url, rawlog = lambda s: log.debug( s )) as rsp:

Alternatively, you could do something like this:

aiohttp.log.client_logger.log( 1, '....' )

This would require users to explicitly enable a logging level of 1 ( which is less even than logging.DEBUG ) in order to opt-in to this behavior.

Describe alternatives you've considered

I created the following abomination to meet my current needs, but it is likely to break everytime the developers sneeze:

# aiohttp_logging.py

from __future__ import annotations

import aiohttp.client_reqrep
import logging
from typing import Any, Tuple, TYPE_CHECKING

if TYPE_CHECKING:
	from aiohttp.connector import Connection

logger = logging.getLogger( __name__ )

OriginalClientRequest_send = aiohttp.client_reqrep.ClientRequest.send
OriginalStreamWriter = aiohttp.client_reqrep.StreamWriter
OriginalClientResponse_start = aiohttp.client_reqrep.ClientResponse.start
OriginalClientResponse_read = aiohttp.client_reqrep.ClientResponse.read

async def LoggingClientRequest_send(self, conn: Connection) -> aiohttp.client_reqrep.ClientResponse:
	logger.debug( f'requesting {self.method} {self.original_url}' )
	return await OriginalClientRequest_send( self, conn )

class LoggingStreamWriter( OriginalStreamWriter ):
	def _write( self, chunk: bytes ) -> None:
		#log = logger.getChild( 'LoggingStreamWriter._write' )
		super()._write( chunk )
		for line in chunk.decode( 'cp437' ).split( '\n' )[:-1]: # -1 because an extra blank lines gets shown otherwise...
			logger.debug( f'C>{line}' )

class LoggingProtocol:
	def __init__( self, protocol: 'Protocol' ) -> None:
		self.protocol = protocol
	
	async def read( self ) -> Tuple[Any,Any]:
		#log = logger.getChild( 'LoggingProtocol.read' )
		msg, payload = await self.protocol.read()
		logger.debug( f'S>HTTP/{msg.version.major}.{msg.version.minor} {msg.code} {msg.reason}' )
		for name, value in msg.raw_headers:
			logger.debug( f'S>{name.decode("cp437")}: {value.decode("cp437")}' )
		logger.debug( 'S>' ) # show blank line between headers and body
		return msg, payload

async def LoggingClientResponse_start( self, connection: Connection ) -> aiohttp.client_reqrep.ClientResponse:
	#log = logger.getChild( 'LoggingClientResponse_start' )
	orig_protocol = connection.protocol
	try:
		connection._protocol = LoggingProtocol( orig_protocol )
		return await OriginalClientResponse_start( self, connection )
	finally:
		connection._protocol = orig_protocol

async def LoggingClientResponse_read( self ) -> bytes:
	#log = logger.getChild( 'LoggingClientResponse_read' )
	data = await OriginalClientResponse_read( self )
	for line in data.split( b'\n' ):
		logger.debug( f'S>{line.decode("cp437").rstrip()}' )
	return data

def monkey_patch() -> None:
	assert aiohttp.client_reqrep.StreamWriter == OriginalStreamWriter, 'already monkey-patched'
	aiohttp.client_reqrep.ClientRequest.send = LoggingClientRequest_send
	aiohttp.client_reqrep.StreamWriter = LoggingStreamWriter
	aiohttp.client_reqrep.ClientResponse.start = LoggingClientResponse_start
	aiohttp.client_reqrep.ClientResponse.read = LoggingClientResponse_read

Related component

Client

Additional context

sample output from a test performed against a little netgear switch on my network:

DEBUG:ace.incpy.aiohttp_logging:requesting GET http://172.16.42.2/
DEBUG:ace.incpy.aiohttp_logging:C>GET / HTTP/1.1
DEBUG:ace.incpy.aiohttp_logging:C>Host: 172.16.42.2
DEBUG:ace.incpy.aiohttp_logging:C>Accept: */*
DEBUG:ace.incpy.aiohttp_logging:C>Accept-Encoding: gzip, deflate
DEBUG:ace.incpy.aiohttp_logging:C>User-Agent: Python/3.9 aiohttp/3.8.1
DEBUG:ace.incpy.aiohttp_logging:C>
DEBUG:ace.incpy.aiohttp_logging:S>HTTP/1.1 200 OK
DEBUG:ace.incpy.aiohttp_logging:S>Connection: close
DEBUG:ace.incpy.aiohttp_logging:S>X-Frame-Options: SAMEORIGIN
DEBUG:ace.incpy.aiohttp_logging:S>X-XSS-Protection: 1; mode=block
DEBUG:ace.incpy.aiohttp_logging:S>X-Content-Type-Options: nosniff
DEBUG:ace.incpy.aiohttp_logging:S>Content-Type: text/html
DEBUG:ace.incpy.aiohttp_logging:S>Cache-Control: no-cache
DEBUG:ace.incpy.aiohttp_logging:S>Expires: -1
DEBUG:ace.incpy.aiohttp_logging:S>
DEBUG:ace.incpy.aiohttp_logging:S><!DOCTYPE html>
DEBUG:ace.incpy.aiohttp_logging:S><html>
(snip)
DEBUG:ace.incpy.aiohttp_logging:S></html>
DEBUG:ace.incpy.aiohttp_logging:S>

Code of Conduct

• I agree to follow the aio-libs Code of Conduct

[webknjaz]

Why didn't you just use Wireshark? When debugging network issues, people tend to end up using it anyway. I don't think that every web framework is supposed to reimplement the wheel.
Do you have any framework examples that do this?

[webknjaz]

Maybe our docs should link to Wireshark? 💭

[remdragon]

Because it's https traffic and I don’t have twilio’s private key to be able to decode the traffic using wireshark. I also sometimes find it useful to log all http conversations in an application so that I can troubleshoot problems after the fact. This is particularly useful for problems that are difficult to reproduce. With regards to other frameworks, I was able to implement a wrapper around the requests library that allowed me to log traffic without much difficulty, but the structure of your code required a lot more monkey-patching.

[webknjaz]

Because it's https traffic and I don’t have twilio’s private key to be able to decode the traffic using wireshark

You should be able to use SSLKEYLOGFILE per https://hynek.me/til/tls-troubleshooting/ / https://gitlab.com/wireshark/wireshark/-/wikis/TLS#tls-decryption.

[remdragon]

Because it's https traffic and I don’t have twilio’s private key to be able to decode the traffic using wireshark

You should be able to use SSLKEYLOGFILE per https://hynek.me/til/tls-troubleshooting/ / https://gitlab.com/wireshark/wireshark/-/wikis/TLS#tls-decryption.

This is helpful to know about wireshark, though it doesn't solve my entire use-case.

The first link you sent shows a really useful hook in SSLContext that would give me what I'm looking for.

However, I would still have a use-case for logging unencrypted traffic, too.

For example, in several of my applications I log successful http client requests/responses at a DEBUG level and failed responses ( any http 4XX for example ) at a WARNING level. This way my users can choose to log all traffic or only traffic that has a problem.

Again, logging this traffic is a boon when troubleshooting applications that aren't working correctly without having to try to reproduce the problem with wireshark running.