A Structured Log using NLog

Using NLog to create human readable logs with a custom Json format

{
    "Level": "INFO",
    "Message": "Request starting HTTP/1.1 GET http://someUrl",
    "Context": "ConnectionId:0HM7A8N54SLT8..."
}

Introduction

Logging is a mandatory thing to have on any application, commonly used for monitoring, error detection and sometimes for audit.

Logging is more than Console.WriteLine, normally it is needed to have different outputs and different levels for each environment.

ASP.NET Core already have built in support and providers, today I will use it with a third party library called NLog to solve the current use cases. 📘 NLog WikiTutorial

This article do not pretend to be a tutorial but instead go strait to the point and expose a possible solution for the enumerated use cases. It is strongly recommended to visit the links referenced on this article.

Needed Use Cases

Note: The following use cases are examples of my needs on a specific project

1. Centralize log configuration;

2. Output target should be only console;

3. Human and machine readable output;

4. Have structured logging on AWS, it supports multi line logs from console target only if they are in JSON format;

5. Filter logs by logged user by logging the user GUID claim;

6. Filter logs by request id, to filter all logs by operation;

7. Filter logs by log level allowing for e.g. error logs;

8. Application monitoring (includes metrics for AWS alarms);

9. Ignore heart bit requests logging;

Hands On over Use Cases

1. In order to centralize logging configuration a option is to create a nlog.config file with all configurations; 📘 NLog file configuration Wiki

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      throwExceptions="true">
  <targets>
    <target name="consoleLog" xsi:type="Console">
      <layout xsi:type="JsonLayout" EscapeForwardSlash="false">
        <attribute layout="${level:upperCase=true}" name="Level"/>
        <attribute layout="${mdlc:UserName}" name="UserName"/>
        <attribute layout="${message}" name="Message"/>
        <attribute layout="${exception:format=tostring,StackTrace}" name="Exception"/>
        <attribute layout="${ndlc}" name="Context"/>
        <attribute layout="${event-properties:item=Metric}" name="Alarm" encode="false"/>
      </layout>
    </target>
  </targets>
  <rules>
    <logger name="*" minlevel="Info" writeTo="consoleLog">
      <filters defaultAction="Log">
        <when condition="contains('${ndlc}','/api/heartbeat')" action="Ignore"/>
      </filters>
    </logger>
  </rules>
</nlog>

2. Configure a console target inside nlog.config; 📘 NLog targets Wiki

3. To achieve readable logs, a structure is needed and also log entries should be meaningful with context. A log layout was defined inside nlog.config; 📘 NLog Configuration options

4. Configure a strong typed JsonLayout will enrich log entries and allowing the AWS to join multiple lines on a single log entry; 📘 Wiki JsonLayout

5. To have the username inside logs automatically it is possible to inject values inside NLog context. I recommend to do so inside a HTTP middleware; 📘 NLog MDLC-Layout-Renderer Wiki

MappedDiagnosticsLogicalContext.Set("UserName", userName);

6. To filter logs associated with the same request it is possible to attach context information and inside the same log item; 📘 Ndlc-Layout-Renderer Wiki

7. To filter logs by level, Include log level property inside JsonLayout;

8. To have additional monitoring information, inject extra property by calling directly NLog method, I recommend to create a extension method;

public static void LogMetric(this ILogger logger, SomeObject obj)
{
    if (logger.IsEnabled(LogLevel.Information))
    {
        var nLogLogger = LogManager.GetCurrentClassLogger();
        var e = new LogEventInfo(LogLevel.Info, "MetricLogger", "");
        e.Properties["Metric"] = JsonConvert.SerializeObject(jsonObj);
        nLogLogger.Log(e);
    }
}

End result

{
    "Level": "INFO",
    "UserName": "User",
    "Context": "ConnectionId:0HM7ATJ6S46BL RequestPath:/someUrl",
    "Alarm": {
        "Count": 3,
        "Event": "SomeEvent",
        "Type": "SomeDataState"
    }
}

9. To ignore some logs, just add a log filter; 📘 Filtering log messages Wiki

Once we have the request context on all logs, it is easy to filter and ignore this logs.

<filters defaultAction="Log">
    <when condition="contains('${ndlc}','/api/heartbeat')" action="Ignore"/>
</filters>

Recomendations

• Choose the correct log level for each log with a criteria, do not forget you have 6 levels to choose from, 📘 NLog log leveis page
• Explore NLog documentation, there are so many options that for sure will fit your needs. 📘 NLog Wiki

Conclusion

Logging is most of the times used for multiple purposes, including real-time monitoring, metrics creation, profiling and bug detection.

For this reason it is difficult to have a single output that fits all purposes.

If, for some reason, your application architecture limits you to have only one target output, think on using a structured log no matter which structure you decide to adopt but follow it.