ToolsPack.Logging 4.0.1

ToolsPack.Logging

Http Logging middlewares

This nuget provides several middlewares of HttpClient allowing to log HTTP requests and responses.

CompactHttpLoggingMiddleware loggingMiddleware = new(logger)
var httpClient = new HttpClient(loggingMiddleware)

//the request and response will be logged
await httpClient.GetAsync("https://api.example.com/user/42?metadata=off");

• CompactHttpLoggingMiddleware produces only ONE log message per request. The log is emitted after receiving the response, the middleware logs both the request, response and the elapsed time in only one log item. In case Exception occurs before receiving the response, the Exception would be logged in the same log item and be re-thrown.

• SimpleHttpLoggingMiddleware produces multiple log messages per requests. It logs the request before sending, then log the response after receiving. The middleware generates a HttpRequestCorrelationId in the logging scope to correlate the request and response log items. In case Exception occurs before receiving the response, only the request would be logged.

• Using the corresponding CustomCompactHttpLoggingMiddleware and CustomSimpleHttpLoggingMiddleware. You would be able

  • to configure the logging level depending on the request/response. You can configure for example:
    • LogLevel.Warning when the response status is not 2XX, and LogLevel.Information otherwise.
    • LogLevel.None for all GET request to avoid logging them.
  • to configure logging redaction depending on the request/response. You can configure for example:
    • Hide the "password:*" value in the request's body of POST https://external-api/registration/user
    • Hide the "bankCardNumber:*" in the response's body of GET https://external-api/payment/*

Recommendation

• Choose CompactHttpLoggingMiddleware over SimpleHttpLoggingMiddleware
• Choose CustomCompactHttpLoggingMiddleware over CustomSimpleHttpLoggingMiddleware

MockLogger

Your test is executing some application codes which log certain messages via the Microsoft.Extensions.Logging library. Once the application codes finished, you want to Assert (or to Verify) that some messages are logged as expected.

There are several ways allowing you to "spy" on the log events happening during the application execution:

• Use FakeLogger in the Microsoft.Extensions.Diagnostics.Testing nuget package. Checkout the FakeLogger example.
• Use the Meziantou.Extensions.Logging.InMemory package
• Use MockLogger of this ToolsPack.Logging nuget package. Checkout the MockLoggerTests.cs for demonstration.

While FakeLogger give you access to the collection of all log events so you can check whatever you wanted. MockLogger is suistable only for simple use cases which you interested in only certain log events, verify if they are logged or not?

Here how MockLogger works:

Step 1: Use a Mock library (such as Moq, NSubstitue..) to instantiate a MockLogger. For eg:

MockLogger _mocklogger = Substitute.For<MockLogger>();

Step 2: Ask your application codes to use the MockLogger by providing (or by injecting) it to your Application codes, for eg:

var diContainer = new ServiceCollection();
diContainer.AddLogging(builder =>
{
    builder.AddMockLogger(_mocklogger);
    
    //you can apply specific filters for MockLogger
    builder
        .AddFilter<MockLoggerProvider>("System", LogLevel.Error)
        .AddFilter<MockLoggerProvider>("Microsoft", LogLevel.Error)
        .AddFilter<MockLoggerProvider>("App.Metrics", LogLevel.Error);
        
    //or else it will follows the global filters
    builder.AddFilter(null, LogLevel.Trace);
});

step 3: Then use your Mock library to spy (NSubstitue.Received(), Moq.Verify..) on the IsLogged hooks of the MockLogger. For eg:

_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Error),
    Arg.Any<EventId>(),
    Arg.Is<Exception?>(ex => ex.Message == "some exception"),
    Arg.Is<string>(s => s.Contains("some error on Greeting")));

If the mockLogger is unable to capture the log message then check the config (or default config) of the filters.

Basic usages

//Act
_mocklogger.LogInformation("haha");
_mocklogger.LogError(new Exception("some exception"), "some error on {method}", "Greeting");

//Assert
_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Information),
    Arg.Any<EventId>(),
    Arg.Any<Exception?>(),
    Arg.Is("haha"));

_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Error),
    Arg.Any<EventId>(),
    Arg.Is<Exception?>(ex => ex.Message == "some exception"),
    Arg.Is<string>(s => s.Contains("some error on Greeting")));

Basic usages for High performance logging

//Logging definition

[LoggerMessage(EventId = 0, Level = LogLevel.Information, Message = "Send request {message}")]
public static partial void LogSendRequestInfo(this ILogger logger, string message);

[LoggerMessage(EventId = 1, Level = LogLevel.Error, Message = "Received something wrong")]
public static partial void LogGetResponseError(this ILogger logger, Exception ex);

//High performance logging

_mocklogger.LogSendRequestInfo("toto");
_mocklogger.LogGetResponseError(new Exception("Failed to do thing"));

//Assert the log content

_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Information),
    Arg.Any<EventId>(),
    Arg.Any<Exception?>(),
    Arg.Is("Send request toto"));

_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Error),
    Arg.Any<EventId>(),
    Arg.Is<Exception?>(ex => ex.Message == "Failed to do thing"),
    Arg.Is<string>(s => s.Contains("Received something wrong")));

Log structuring

In log structuring, a log item is usually a list of objects (key-value) rather than just a string.

Your application codes might also generate many log items with the same text message but with different objects in the log structure. In this case, Asserting (verifying) the log text message is not very interesting, you usually want to spy on the log structure instead.

//Logging definition

[LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "The person {person} odered {order}")]
public static partial void LogStructuringSampleInfo(this ILogger logger, SomePersonObject person, SomeOrderObject order);

//High performance logging, it will generate a structured log which contains 2 objects

_mocklogger.LogStructuringSampleInfo(new SomePersonObject("Hiep", 18), new SomeOrderObject("#1", 30.5));

//Assert the log content

using LogState = IReadOnlyList<KeyValuePair<string, object?>>;

_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Information),
    Arg.Any<EventId>(),
    Arg.Any<Exception?>(),
    Arg.Is<string>(msg => Regex.IsMatch(msg, "The person .* odered .*")),
    Arg.Is<LogState>(state => AssertLogStructuring(state)));

//verify that the "person" and "order" objects in the log item got the expected values
private static bool AssertLogStructuring(LogState state)
{
    var person = (from s in state
                    where s.Key == "person"
                    select s.Value as SomePersonObject).First();

    var order = (from s in state
                    where s.Key == "order"
                    select s.Value as SomeOrderObject).First();

    return person.Name == "Hiep" && person.Age == 18 && order.Id == "#1" && order.Amount == 30.5;
}

Use MockLogger to spy on other loggers used by your application codes

You have to add the MockLogger to the logging pipeline of your application, so that it can "monitor" all log events generated by your application codes:

//let's say you have a service provider similar to the one in your ASP.NET app
var diContainer = new ServiceCollection();
diContainer.AddLogging(builder =>
{
    //add the MockLogger to the logging pipeline
    builder.AddMockLogger(_mocklogger);
});
var services = diContainer.BuildServiceProvider();

//let's say your application is using this logger (which is not our MockLogger)
ILogger<MyApp> someAppLogger = services.GetRequiredService<ILogger<MyApp>>();

//your application logged something with this logger
someAppLogger.LogInformation("haha");

//Assert that application logged the expected message whatever the logger is used
_mocklogger.Received().IsLogged(
    Arg.Is(LogLevel.Information),
    Arg.Any<EventId>(),
    Arg.Any<Exception?>(),
    Arg.Is("haha"));

Use MockLogger in XUnit side by side with real loggers (Serilog for example)

Checkout full codes in TestOutputHelperExtensionTests.cs.

The example got a nice Helper to configure logging on the stack XUnit, NSubstitute..

//config serilog
var serilogLogger = new LoggerConfiguration()
    .MinimumLevel.Verbose(); //serilog can see all the log events
    .WriteTo.Seq("http://localhost:5304/")
    .WriteTo.TestOutput(testOutputHelper)
    .WriteTo.File("app.log")
    .CreateLogger()

//create mockLogger with NSubstitute
var mockLogger = Substitute.For<MockLogger>();

//mix Serilog and mockLogger together
var loggerFactory = LoggerFactory.Create(builder => {
    builder
        .AddSerilog(serilogLogger) 
        .AddMockLogger(mockLogger)

        //Make mockLogger receive  all log events, similar to serilog
        .AddFilter(null, LogLevel.Trace); 
});

//Log something:
var logger = loggerFactory.CreateLogger();
logger.LogInformation("hello");

Note: To display the Xunit's Tests Output on the command line:

dotnet test --logger "console;verbosity=detailed":

More info

Display logs of XUnit's extensibility classes (IClassFixture, ITestCaseOrderer...) in the Test console

The XUnit test console (ITestOutputHelper) is only available for unit tests. If the logs messages in XUnit's extensibility classes (IClassFixture, ITestCaseOrderer...) won't show up in the test console.

But there is a way to make it happening: checkout this Tutorial.

ElapsedTimeLogger

Micro-benchmark a part of code to investigate on performance. This is a normal ILogger or more precisely a decorator to a ILogger, when you use it to log a message it will "decorate" the message with the duration (elapsed time) since the previous logged message.

class MyCalculator
{
    private static readonly ILogger Log = loggerFactory.CreateLogger<ElapsedTimeLoggerTests>();

    public void Process()
    {
        using (var etw = ElapsedTimeLogger.Create(Log, "blockCodeName"))
        {
            ...
            etw.LogInformation("step 1");
            ...
            etw.LogDebug("step 2");
            ...
            etw.LogInformation("Step 3)");
            ...
        } //"sum up log" is displayed here
    }
}

• The etw wrap the usual logger Log, we use etw to log message instead of the usual Log
• the blockCodeName is repeated in the start of each log message, so that we can filter log message by "blockCodeName"
• Each log message will display the elapsed time (in micro-second) since the last log message.
• A sum up log will display the total elapsed time (in micro-second) when the etw object is disposed.

22:56:59,866 [DEBUG] Begin blockCodeName
22:56:59,970 [INFO ] blockCodeName - 102350 mcs - step 1
22:57:00,144 [DEBUG] blockCodeName - 173295 mcs - step 2
22:57:00,259 [INFO ] blockCodeName - 114036 mcs - Step 3)
22:57:00,452 [INFO ] End blockCodeName : Total elapsed 585436 mcs

Auto Jump Log Level

var etw = ElapsedTimeLogger.Create(Log, "checkIntraday").InfoEnd().AutoJump(150, 250).AutoJumpLastLog(500, 1000)

• The log level will auto jump to INFO if the elapsed time exceeds 150 ms
• The log level will auto jump to WARN if the elapsed time exceeds 250 ms
• The above sum up log will switch to INFO if the total elapsed time exceeds 500 ms
• The above sum up log will switch to WARN if the total elapsed time exceeds 1 sec

Customize Start Context and End context

var etw = ElapsedTimeLogger.Create(Log, "foo", "Start_context", "End_context");

will give

22:56:59,866 [DEBUG] Begin Start_context
22:56:59,970 [INFO ] foo - 102350 mcs - step 1
22:57:00,144 [DEBUG] foo - 173295 mcs - step 2
22:57:00,259 [INFO ] foo - 114036 mcs - Step 3)
22:57:00,452 [INFO ] End End_context : Total elapsed 585436 mcs

We often display the parameter of the functions in the "Start context". Example:

public void process(string val, bool useCache)
{
    var context = string.Format("process(val={0}, useCache={1})", val, useCache);
    using (var etw = ElapsedTimeLogger.Create(Log, "process", context))
    {
        ...
        etw.LogInformation("step 1");
        ...
        etw.LogDebug("step 2");
        ...
        etw.LogInformation("Step 3)");
        ...
    } //"sum up log" is displayed here
}

will give

22:56:59,866 [DEBUG] Begin process(val=Lorem ipsum, useCache=true)
22:56:59,970 [INFO ] process - 102350 mcs - step 1
22:57:00,144 [DEBUG] process - 173295 mcs - step 2
22:57:00,259 [INFO ] process - 114036 mcs - Step 3)
22:57:00,452 [INFO ] End process(val=Lorem ipsum, useCache=true) : Total elapsed 585436 mcs

Other benchmark library

• If you want to optimize a particular static (and stateless) function, checkout BenchmarkDotNet project. See video tutorial here. (Unlike other project, the ElapsedTimeLogger is just a ILogger so it fits to be injected to any production application)
• https://miniprofiler.com/dotnet/