Skip to content

Logging

Patrick Svaiter edited this page Jul 10, 2018 · 11 revisions

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.

ASP.NET Core apps are ready for dependency injection and you just need to add the logger and OneHttpClient.HttpService to the service collection. The example below shows how you should do it in your ConfigureServices method.

public void ConfigureServices(IServiceCollection services)
{
    // stuff here

    services.AddSingleton<IHttpService, HttpService>();

    // more stuff here
}

Disabling 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 information about the elapsed time of a request in log messages, log structured data and exceptions.

This time has the minimum overhead possible. The overhead created by OneHttpClient is surely NOT included in the elapsed time measured.

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.Get("https://jsonplaceholder.typicode.com/posts/1"),
    _http.Post("https://jsonplaceholder.typicode.com/posts/1"),
    _http.Put("https://jsonplaceholder.typicode.com/posts/1"),
    _http.Patch("https://jsonplaceholder.typicode.com/posts/1"),
    _http.Delete("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)? 😉

Clone this wiki locally