Logging

OneHttpClient provides logging of the following events of an HTTP request:

• Request starting - Right before starting the request
• Request finished - Right after the response has arrived completely

Usage

The HttpService ctor accepts an optional logger component. The logger must implement the Microsoft ILogger interface and you can pass it manually or let a DI container inject it automatically.

Want to disable logging output from OneHttpClient?

Filter out the category OneHttpClient.HttpService in the logging configuration. The way you do this may be different depending on how you configure the log in your application.

The example below works in an ASP.NET Core application. It sets up NLog as the logger and "tells" the logging providers to bypass all log entries of category OneHttpClient.HttpService.

private static IWebHost BuildWebHost()
{
    var webHost = WebHost.CreateDefaultBuilder()
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders();
            logging.SetMinimumLevel(LogLevel.Information);
            logging.AddFilter("OneHttpClient.HttpService", LogLevel.None);
        })
        .UseNLog()
        .UseStartup<Startup>()
        .Build();

    return webHost;
}

Semantic logging

Expect the following fields for Request starting:

• GuideNumber
• HttpMethod
• RequestUri

Expect the following fields for Request finished:

• GuideNumber
• ElapsedMilliseconds
• StatusCode

Elapsed time

OneHttpClient provides the elapsed time of a request in log messages, in log structured data and in timeout exceptions.

This elapsed time is the most accurate time as possible as it's measured around the real call made by HttpClient from .NET. Though if you take your own measure around a public method of OneHttpClient you will experience slightly higher times, as it takes into account the (yet very low) overhead added by this package. Prefer to use the provided elapsed time instead.

The overhead is usually < 1ms (without de/serialization).

Guide number

When making multiple requests in a short period of time, you may get lost trying to figure out which request a specific elapsed time belongs to. The guide number is a 6-character random string that will help you with that. Its only purpose is to link the request to the corresponding response.

See the example below. The code is making five requests in parallel to a fake online REST API. There's a high chance that the log entries get interleaved.

Task.WaitAll(
    _http.GetAsync("https://jsonplaceholder.typicode.com/posts/1"),
    _http.PostAsync("https://jsonplaceholder.typicode.com/posts/1"),
    _http.PutAsync("https://jsonplaceholder.typicode.com/posts/1"),
    _http.PatchAsync("https://jsonplaceholder.typicode.com/posts/1"),
    _http.DeleteAsync("https://jsonplaceholder.typicode.com/posts/1")
);

_http is a field of type OneHttpClient.IHttpService.

See the result out of a real run.

2018-07-10 00:16:22.7939 | INFO | OneHttpClient.HttpService | Request 68F943 starting GET https://jsonplaceholder.typicode.com/posts/1 
2018-07-10 00:16:22.7939 | INFO | OneHttpClient.HttpService | Request 7E3129 starting POST https://jsonplaceholder.typicode.com/posts/1 
2018-07-10 00:16:22.7939 | INFO | OneHttpClient.HttpService | Request 835C81 starting PUT https://jsonplaceholder.typicode.com/posts/1 
2018-07-10 00:16:22.7939 | INFO | OneHttpClient.HttpService | Request 9AF9D1 starting PATCH https://jsonplaceholder.typicode.com/posts/1 
2018-07-10 00:16:22.7939 | INFO | OneHttpClient.HttpService | Request 54E3DD starting DELETE https://jsonplaceholder.typicode.com/posts/1 
2018-07-10 00:16:22.9059 | INFO | OneHttpClient.HttpService | Request 68F943 finished in 111.2822 ms [200] 
2018-07-10 00:16:23.0490 | INFO | OneHttpClient.HttpService | Request 7E3129 finished in 253.8469 ms [404] 
2018-07-10 00:16:23.6556 | INFO | OneHttpClient.HttpService | Request 54E3DD finished in 859.0252 ms [200] 
2018-07-10 00:16:23.9332 | INFO | OneHttpClient.HttpService | Request 835C81 finished in 1137.6146 ms [200] 
2018-07-10 00:16:23.9332 | INFO | OneHttpClient.HttpService | Request 9AF9D1 finished in 1138.0379 ms [200] 

Without the guide number, would you be sure the 404 response belongs to the second request made (POST)? 😉