Sitecore Experience Commerce: Improved Serilog Configurations

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.

Sitecore Experience Commerce: Methods for Logging and Command Messaging

In this article, we will look at the APIs available for logging to the logging framework and applying command messages to the CommerceContext.

The reason for grouping these two subjects together is due to seeing a lot of confusion around these areas when reviewing developers' code in the field; there is some overlap between them, which is often overlooked.

In Sitecore Commerce, logging is based on Microsoft.Extensions.Logging, and the Sitecore Commerce Engine SDK is setup to utilise the SeriLog diagnostic library for logging.

The CommandMessages are flushed to calling CommerceCommands via the completion of the CommandActivity and are included in the response object of CommandsController APIs.

Logging and command messaging occurs within methods of the CommercePipelineExecutionContext and the CommerceContext.

CommercePipelineExecutionContext

LogInfoIf

public void LogInfoIf(bool conditionResult, string info);

Intuitive enough, the LogInfoIf method will log an Information level entry, info, if the conditionResult is met.

Abort

public override void Abort(string reason, object data);

The Abort method will abort the pipeline and will create an Error level log entry if the reason message doesn't contain the magic string "Ok|".

It's also worth noting that this method is intended to abort the executing pipeline first and foremost, and the log entry is secondary. It is not intended solely for the purpose of logging.

Note: The data object would normally return the current CommercePipelineExecutionContext.

CommerceContext

AddDataMessage

public virtual void AddDataMessage(string messageType, string dataMessage);

The AddDataMessage will add the dataMessage to the command messages. It will also add the dataMessage to the logger at the Information level.

Tip: Avoid setting Debug level messages to avoid spamming your local development logs, which are defaulted to the Information level.

AddMessage

public virtual void AddMessage(CommandMessage message);

AddMessage will add a CommandMessage to the command messages.

The message will not invoke the logger.

AddMessage (Alternate)

public virtual Task<string> AddMessage(string code, string commerceTermKey, object[] args, string defaultMessage = null);

The overloaded AddMessage method's logging behaviour is as follows:

  • Message codes of ValidationError or Warning will add a Warning message to the Logger.
  • All exception types will be logged using the LogException method. See LogException for more details.
  • An Error will also be logged as an Error.

For the CommandMessages, the localised message will attempted to be retrieved from Sitecore, using the commerce term key provided, and further formatted/interpolated with the args provided.

LogException

public virtual void LogException(string caller, Exception ex);

The LogException method will log an exception as an error with the exception message and stack trace details.

LogExceptionAndMessage

public virtual void LogExceptionAndMessage(string caller, Exception ex);

The LogExceptionAndMessage logs the exception as per the LogException method, however the exception message will be added to the CommandMessages at the Error level in addition.

Logger

public ILogger Logger { get; }

The Logger exposes the can be utilised to add the standard log-level entries to it, being:

  • LogDebug
  • LogInformation
  • LogWarning
  • LogError
  • LogCritical

Sitecore Experience Commerce: Configuring Debug Logging

In this article, we will look into the steps necessary in order to reduce the log level to Debug in the Retail Demo for Sitecore Commerce 8.2.1.

In LoggingExtentions.cs, the MinimumLevel is set to Information, therefore regardless what the Logging.LogLevel.Default and Serilog.MinimumLevel configurations in config.json are set to Debug log requests will not be logged.

var loggingConfig = new LoggerConfiguration()
		.Enrich.With(new ScLogEnricher())
		.MinimumLevel.Information();

By updating this line to MinimumLevel.Debug() , we are now able to drop the log level configurations to Debug and see the output in the log file.

"Logging": {
	"LogLevel": {
		"Default": "Debug"
	},
},
"Serilog": {
	"MinimumLevel": "Debug"
}
1 14:01:53 INFO Registering Pipeline Block 'Project.Commerce.Engine.Pipelines.Blocks.ValidateSitecoreConnectionBlock'
3 14:01:53 DEBUG [PipelineStarted]
3 14:01:53 DEBUG Block execution started for '"pipelines:blocks:StartNodeBlock"'
15 14:01:53 INFO [NodeStartup] ContactId='Deployment01_a1adc4875f9a4ef6b9513d9379373d2c',Environment='GlobalEnvironment'
15 14:01:53 DEBUG Block execution completed for '"pipelines:blocks:StartNodeBlock"'
15 14:01:53 DEBUG Block execution started for '"pipelines:blocks:StartNodeLogConfigurationBlock"'
15 14:01:56 WARN Performance Counter Category 'SitecoreCommerceCommands-1.0.2' not found
15 14:01:56 WARN Performance Counter Category 'SitecoreCommerceMetrics-1.0.2' not found
15 14:01:56 DEBUG Block execution completed for '"pipelines:blocks:StartNodeLogConfigurationBlock"'
15 14:01:56 DEBUG [PipelineCompleted]

Note: It is not recommended that Debug log levels and set in the production environment and when using Debug log levels in any environment, it is recommended to only utilise this log level for the smallest window necessary to avoid excessive logging as this will eat away at the storage space quite quickly.