RFC: better logging

[vgavro]

I'm reviewing logging in httpx-retries, and have some suggestions.

Current logging
L1. transport.py: debug: handle_request_started, handle_request_finished - those logs are totally replaced by providing logging to Client.event_hooks["request"/"response"] and doesn't make much sense IMHO - as they are not retry transport specific at all.
L2. transport.py: debug: retry_operation (sync/async) request, response|exception - this is most useful log, lack sleep information
L3. retry.py: warning: Retry-After has no timezone, Retry-After invalid date
L4. retry.py: debug: sleep/asleep time (this is not much useful without _retry_operation request/response|exception info). (considering you have requests in parallel, you don't even understand which sleep actually applies to which retry)

What I propose to have
T1. (high severity) One log record for L2 and L4 - this is main issue here.
T2. (middle severity) Possibility to override T1 logging to use structlog, for example, based on application logic, not to extract request/response parameters from formatted string.
T3. (low severity) maybe (what do you think) drop L1 log entirely.

How to implement
To achieve T1, we need to either calculate sleep with public method after increment, log in transport, then call sleep(calculated_sleep) from transport.
Or better - pass (request, response) to Retry.sleep(), and call Retry._log_sleep(request, response, time_to_sleep) there, which can default to current implementation, but can be easily overriden on inheriting Retry class.
What do you think?.... problem is - passing request to Retry.sleep is breaking public api, BUT i don't think it's a big issue here... IMHO other options worse.

Thank you for your time on this! i'll be glad to create PR on this after your feedback.

[vgavro]

for case T1/T2 it's already used like this - #22 (comment) - the problem here that request object isn't available here, and to resolve this problem - it needs to be set via local context, which may be really annoying, also considering request can raise exception in the end - so local context needs to be set/unset on transport level then...so.. i guess it's easier just to pass request object to Retry.sleep

[vgavro]

@will-ockmore other approach i can think of - is implementing retry hook - same way as it's implemented for request/response in httpx client. Problem is - hooks are for Client, not Transport, and they are not passed to request object.
It's mostly used for logging request/response in easier way, restrict/validate/modify request/respone, so this is good mechanics, but to be honest i don't see usefull cases for this hook for retry event except logging, not to say we can't pass this hook to client - we need to pass it to transport initialization.. .so inheriting Retry looks like sufficient enough approach, but i don't have strong opinion on that. what do you think?

[will-ockmore]

Great writeup @vgavro - agree with your take on the L2 / L4 discrepancy. One log is almost certainly better.

Also happy to drop L1.

In general I think that perhaps Retry shouldn't do any logging at all (except for the warning log, it always cares about Retry-After); maybe we introspect the Retry object here and construct a canonical log line for the retry attempt. I can't see any issues with this approach other than the need to make _calculate_sleep part of the public API; this feels cleaner than passing in the full request object.

Retry hook is interesting. I also am struggling to see other use cases for it. Maybe there are some out there

On structured logging: this is a separate can of worms IMO, probably worth a separate issue if people continue to run into it.

[vgavro]

Well, i don't think canonical log only is good enough, consider not only structlog, but also metrics telemetry. Of course on merging #75 with deplected retry in response.extensions you can do this telemetry in Client.hooks["response"], but it will not be available for failed retries, and will be available with delay for successful retries, which is also not good enough.
Maybe hook approach isn't so bad in that case if our goal really is - give as good DX as possible. Then real log entry doesn't matter much.

So - better DX - retry hook - slightly more complexity.
sligtly worse DX - ability to inherit (in transport or in Retry object, doesn't make much difference for me, but better to override as small amout of code as possible)...

And better default log entry - I agree with you - should be just there. You're right that it's different tasks - ability to make hook for telemetry/structlog is one thing, and overriding "default" log entry - is something unexpected and we shouldn't mix this two tasks....