Tag: logging

In this article, we will look at a few ways to configure the Serilog Logging to improve the ability to troubleshoot via logs.

Introduction

The LoggerConfiguration is defined in Startup.cs in the Commerce Engine project and will be created if the Logging.SerilogLoggingEnabled setting in the config.json file is true. The configuration is as follows:

Log.Logger = new LoggerConfiguration()
				.ReadFrom.Configuration(this.Configuration)
				.Enrich.FromLogContext()
				.Enrich.With(new ScLogEnricher())
				.WriteTo.Async(
					a => a.File(
						$@"{Path.Combine(this._hostEnv.WebRootPath, "logs")}\SCF.{DateTimeOffset.UtcNow:yyyyMMdd}.log.{this._nodeInstanceId}.txt",
						this.GetSerilogLogLevel(),
						"{ThreadId:D5} {Timestamp:HH:mm:ss} {ScLevel} {Message}{NewLine}{Exception}",
						fileSizeLimitBytes: fileSize,
						rollOnFileSizeLimit: true),
					bufferSize: 500)
				.CreateLogger();

With a little investigation into open source Serilog.Sinks.File repo, and an understanding of the Commerce Engine configuration, we can look to improve the logging configuration.

Log File Enhancements

Updating the Log File Name with Local Timezone

When the Commerce Engine initialises, it creates a log file with the the naming convention of SCF.<date>.log.<node instance id>.txt, e.g. SCF.20190902.log.03d49b837f214f55b815ee7adbba5ec.txt.

By default, Serilog uses the DateTime.Now in the outputTemplate, however the Commerce Engine configures the path property with a UTC timestamp. This means that if the date applied to the filename is not a true indication of the system date.

To resolve this, we can simply update the path property to use DateTimeOffset.Now.

Creating a New Log File Each Day

Creating a new log file each day ensures that all log entries for any given log file will pertain to a single day. No more do we have to review the rolling logs spanning multiple days, with a fine-tooth comb, identifying how many cycles of 24 hour time have passed to determine the date of log entries.

We can achieve this by setting the rollingInterval argument to RollingInterval.Day. We will also need to configure an additional period to the path parameter where the extension is specified {this._nodeInstanceId}..txt.

a => a.File(
	 $@"{Path.Combine(this._hostEnv.WebRootPath, "logs")}\SCF.{DateTimeOffset.UtcNow:yyyyMMdd}.log.{this._nodeInstanceId}..txt",
	 this.GetSerilogLogLevel(),
	 "{ThreadId:D5} {Timestamp:HH:mm:ss} {ScLevel} {Message}{NewLine}{Exception}",
	 fileSizeLimitBytes: fileSize,
	 rollOnFileSizeLimit: true,
	 rollingInterval: RollingInterval.Day)

By changing the rollingInterval, Serilog will append a date/time stamp to the file name, prior to the rolling log index, based on the specificity of the interval. For example, setting the rollingInterval to Day will append the date format yyyyMMdd, whereas setting it to the minute will append the date/time format of yyyyMMddHHmm.

This date/time format appended by Serilog when using rolling intervals is hard-coded and cannot be configured.

The additional period will separate the node instance id from the date, and with the change to the rollingInterval parameter, the date will be listed twice in the filename, e.g. SCF.20190902.log.03d49b837f214f55b815ee7adbba5ec1.20190902.txt.

The difference between the two occurences is the first instance is a constant value while the second is dynamic. When specifying the date format in the filename from the previous step this is a constant value that is set during the initialisation of the Commerce Engine, whereas the second date format instance is part of the Serilog library and during the creation of the daily logs will update this value, e.g.

• SCF.20190902.log.03d49b837f214f55b815ee7adbba5ec1.20190902.txt
• SCF.20190902.log.03d49b837f214f55b815ee7adbba5ec1.20190903.txt
• SCF.20190902.log.03d49b837f214f55b815ee7adbba5ec1.20190904.txt

Removing the date from the beginning of the filename will still allow the files to be sorted by filename in descending order while the Commerce Engine has only been initiliased once, however with deployments and manual resets a new guid will be created to represent the node instance id.

Instead, sorting by date modified will provide an accurate timeline, however this won’t separate the NodeConfiguration files from the log files as per sorting by filename.

Adding the Date to the outputTemplate Timestamp

If you are a fan of rolling logs spanning multiple days, then having the date specified in the timestamp will be beneficial.

To achieve this, simply update the outputTemplate parameter’s Timestamp to include the date in the desired format. e.g. {Timestamp:dd/MM/yy HH:mm:ss}.

00027 30/08/19 11:28:11 INFO Executing action method "Sitecore.Commerce.Plugin.Carts.CartsController.Get (Sitecore.Commerce.Plugin.Carts)" with arguments (["Default4c29a122-a190-44f3-ab30-baa79629155dStorefront"]) - ModelState is Valid

Summary

We looked at some of the most useful configuration enhancments to improve our ability to troubleshoot the Commerce Engine via log files. While there are potentially other configurations to further improve logging, Creating a New Log File Each Day appears to have the most benefits.