Logging in HttpClients
I want to propose that logging in the HttpClient pipeline is fundamentally two-stage. We log at the beginning of the pipeline (outer) and at the end of the pipeline (inner).
To understand why this is important imagine that you've got message handlers plugged in for reliability (retries) and for service discovery. This might look like:
HttpClient
-> Logging (outer)
-> -> Reliability
-> -> -> Service Discovery
-> -> -> -> Logging (inner)
-> -> -> -> -> HttpClientHandler (actually does HTTP)
What a request flow might look like (basically) when we have a problem and have to retry - let's say a server goes down - and when we retry the service discovery handler gives us a different server. The logs might look like this (use your imagination):
INFO Starting processing HTTP GET http://myserver/api/products/17
INFO Resolved myserver to myserver1.azure.com
INFO Sending HTTP request GET http://myserver1.azure.com/api/products/17
INFO Got HTTP response 500 - Internal Server Error
INFO Retrying request in 2 sec - retry count 1
INFO Resolved myserver to myserver2.azure.com
INFO Sending HTTP request GET http://myserver2.azure.com/api/products/17
INFO Got HTTP response 200- OK from GET http://myserver2.azure.com/api/products/17
INFO Completed processing 200- OK
Some principles
- Assume the URL will change between the beginning of the pipeline and end
- Assume that there is a 1:* relationship between logical requests (call to HttpClient) and physical requests (actual HTTP)
- Assume individual components will need their own logging (retries, auth, service discovery)
- Assume individual components might need to do their own network calls (auth, service discovery)
Additionally, we want the configuration experience for logging to make you happy. To me that means that you can:
- Adjust logging levels for an individual named HttpClient
- Get enough information from high-verbosity logging to understand what was sent and received in terms of HTTP without needing to debug
Proposal
Ok, now time for a strawman proposal. For the purposes of examples, I'll assume we're using a 'github' named client.
Part 0 Logger Names:
Each client has a named source for the 'outside' (logical) and 'inside' (physical). Here's my humble suggestions:
Outer: `System.Net.Http.HttpClient.github`
Inner: `System.Net.Http.HttpClient.github.ClientHandler`
Additional handlers like service discovery and reliability are encouraged to use source names like System.Net.Http.HttpClient.github.Polly
or System.Net.Http.HttpClient.github.ConsulServiceDiscovery
This way you can configure the levels for sources like System.Net.Http.HttpClient
and broadly configure all concerns for all clients or System.Net.Http.HttpClient.github
and configure all concerns for github.
Part 1 Scopes:
The outer logger will create a scope and attach the initial request HTTP method, and URL.
There's no need for a scope in the inner logger since we'd only be surrounding the HttpClientHandler
at that point, and we don't expect the HttpClientHandler
to know about our logging framework - these implementations come from the BCL.
I think for now we'd recommend that individual message handlers inside the pipeline only create a scope if they are doing an additional remote call. For instance if I write a message handler that can authenticate and get a token for an API server - then the remote call to get the token should be wrapped in a scope. The default guidance is not to create a scope, but there may be reasons why you want to if the process is complex or involves remote resources.
Part 3 Logging levels:
I think we should treat all 500s as error and log them as errors when they reach the outer handler.
Other than that (concerning 400s) - for now I think we should just use the Info and Debug levels for logging. Trying to decide what's an error or warning is a bit tricky and quickly leads down the path of special-casing specific status codes. I'd rather be cautious here and avoid being too noisy.
Note: Let's get feedback on this, I've thought about it a fair bit and haven't come up with a set of ideas that I really believe in.
Part 4 Default logging at Info level:
The goal of logging at Info level is to present the basic information and help you know whether the request was a success or not. Info level logging could help you know things like "The user's request failed because call to api.github.com
is hitting a rate limit". Besides obvious stuff we don't expect info to tell you enough to know exactly what was sent and what was received.
So what this looks like:
Outer: logs outgoing HTTP Method and URL - logs incoming status code and status code text - logs timing
Inner: logs outgoing HTTP Method and URL - logs incoming status code and status code text - logs timing
Note: Is this too verbose? Should we have the inner handler do Debug only? We could also do something like only use the inner handler when you have some other handlers.
Part 5 Default logging at Debug level:
Debug logging - bring on the spam ๐
The goal here is now to give you lots of information about what's going in and out over the wire. Both outer and inner loggers will also log all headers, and the HTTP version, giving you everything except the body.
We also probably want to give you some additional details like what kind of HttpContent
you are sending/receiving (when appropriate).
This is nice because you get a few clickstops for configuring logging:
set System.Net.Http.HttpClient.github
to Info
Now you get basic high level logging, this is the default experience
set System.Net.Http.HttpClient.github
to Info
set System.Net.Http.HttpClient.github.ClientHandler
to Debug
Now you get high level logging for each logical operation, but fill input and output logging for each HTTP request that goes over the wire
set System.Net.Http.HttpClient.github
to Debug
Now you get the full firehose, including all logging from components like service discovery and polly ๐
Note: What about the body? We could log incoming and outgoing bodies in some selective cases. HttpClient already has support for on-demand buffering. We could consider this on debug, but I kinda want to wait and see.