Show response body when debug logging enabled

[raxod502]

Suppose I'm getting an HTTP error from the server DAV endpoints when running vdirsyncer. I then add -vdebug as suggested by the error message from vdirsyncer, expecting to see information would tell me the reason for the failure.

Unfortunately, while vdirsyncer logs the request headers and body, as well as the response status code and headers, it does not log the actual response body from the server, which is where the actual error would most likely be found. Instead, it logs this:

debug: <StreamReader 339 bytes eof>

The log in question is here:

vdirsyncer/vdirsyncer/http.py

Line 224 in 388c16f

logger.debug(response.content)

I'm not sure how a user is expected to find the error message, except by repeating the HTTP request themselves and seeing what the server returns.

I thought it might be easy to contribute an improvement for this (log the response body on -vdebug), but it turns out to be a bit complicated. Firstly, if you just read the body:

logger.debug(await response.content.read())

Then it consumes the body and it can no longer be read by vdirsyncer subsequently. It would be necessary to make a copy of the response object, but I could not find any API method for doing this exposed by aiohttp or requests.

Next, I noticed the comment:

vdirsyncer/vdirsyncer/http.py

Lines 178 to 179 in 388c16f

	# TODO: rewrite using
	# https://docs.aiohttp.org/en/stable/client_advanced.html#client-tracing

I implemented it, following https://docs.aiohttp.org/en/stable/client_advanced.html#aiohttp-client-tracing and https://docs.aiohttp.org/en/stable/tracing_reference.html#aiohttp.TraceConfig.on_response_chunk_received, and added to vdirsyncer.http:

async def trace_response_chunk_received(session, trace_config_ctx, params):
    logger.debug(params.chunk)

trace_config = aiohttp.TraceConfig()
trace_config.on_response_chunk_received.append(trace_response_chunk_received)

I passed trace_configs=[http.trace_config] to the instantiations of ClientSession in other modules. However, this did not work. I discovered that on_response_chunk_received does not function as documented, as mentioned in aio-libs/aiohttp#5324.

At this point I decided to file this issue with my findings.

[WhyNotHugo]

Then it consumes the body and it can no longer be read by vdirsyncer subsequently. It would be necessary to make a copy of the response object, but I could not find any API method for doing this exposed by aiohttp or requests.

Copying the response wouldn't work; await response.content.read() actually streams the response's body from the server and returns that. You can no longer fetch the response's body again after that.

The response function therefore can't log the body and return the underlying response, because the caller would then be unable to read the response itself.

[raxod502]

The response function therefore can't log the body and return the underlying response

What I mean is slightly more subtle: not make a copy of the response body without streaming it, but rather stream the response body, then make a copy of the entire response object, whose content just points to the local buffer that has already been streamed, in the manner of BytesIO. I've seen this pattern used occasionally when dealing with one-time-use stream objects which need to be modified in some way by intermediate code.