The Problem
At Argo, our solution is composed of several different micro services that work together to produce the end results. A service can call another service which can call another service, and so on, to provide the final payload to the caller. This means that there are many layers of calls with multiple log files and possibly on multiple servers. Tracking a single call through several services can be a daunting task.
The source code is available on GitHub via this link.
Tracking across Layers
In order to track service calls across service boundaries, Argo introduced the concept of the “Unique Id” (UID). This UID originates from the caller that calls the first service in the chain of calls. The caller generates a GUID value and passes it in the header of the call as the UID. A system of logging was then created whereby the UID was extracted from the header at the time the log message was written. This shielded the developer from having to extract the UID from the header for every log message that was written.
When a service had to call another service to complete its process, it passed along the UID in the header of the call. That service would extract the UID from the header and then use that in all of its log file entries. Doing this created a single piece of data (UID) that could be used across all log files to find the entries in a log file related to a specific call.
Prior to the introduction of PostSharp, Argo relied on developers to create log entries. These log entries needed to be meaningful to someone who would be reading the logs and would be able to determine what was happening. This created inconsistent logging that did not always provide the information that was needed to track down issues. What was needed was a way to generate consistent log file entries that provided useful insight into what was happening in the service. These log file entries had to be low maintenance and needed to adapt as code changed over time.
Enter PostSharp
Argo had been looking at the PostSharp solution for some time. When a new project became available, Argo made the decision to give PostSharp a try and to use the new project as a “Proof of Concept” for using PostSharp as its logging solution. Argo also made the decision to use NLog as its backend logging solution and to write services in NET Core.
Injecting the Unique ID into PostSharp logs
The UID is an important piece of data for Argo as explained above. What was needed was a way to inject the UID into every call related to a given service call without having to write code over and over again. After some discussion with the PostSharp team, they recommended logging within the context of an activity. That is discussed below.
Middleware
Net Core has the concept of Middleware. Using Middleware, developers can intercept a call and then make decisions before processing the call forward. Argo made use of this technology, writing custom middleware, as a way to intercept the call and provide the start of the logging activity for that call. Setting this up is as easy as adding a “use” clause in the Configure method in the startup file. (ServiceTraceMiddleware is the custom class that handles this middleware functionality.)
app.UseMiddleware<ServiceTraceMiddleware>();
In the middleware, several steps take place to set up the logging and inject the UID into the logging calls that are generated by PostSharp.
- Extract the UID from the header
- Create an instance of LoggingPropertyData (class) and assign it the value for the UID. (This class has a property called UniqueId.)
- Create an activity and provide the properties to log.
- Move to the next call in the series
- Once the call returns, set the outcome to complete the activity.
Here is the code to do that.
var loggingPropertyData = new LoggingPropertyData { UniqueId = uniqueId };
OpenActivityOptions options = new OpenActivityOptions(loggingPropertyData);
using (var activity = _logSource.Default.OpenActivity(FormattedMessageBuilder.Formatted("Start request"), options))
{
// Do logging or whatever
await _next(context); // Move to the next item in the pipeline
// Do more stuff if desired
activity.SetOutcome(PostSharp.Patterns.Diagnostics.LogLevel.Info, FormattedMessageBuilder.Formatted("Request Completed."));
}
The variable _logSource is defined as a static variable on the class as follows. This is the PostSharp LogSource instance.
private static readonly LogSource _logSource = LogSource.Get();
Extracting the UID
Getting the UID into the logging messages doesn’t do any good if it isn’t written out to the log files. To do this, a custom backend and record builder were needed. Since PostSharp already has a backend for NLog, all that was needed was to inherit from that and add the code needed to extract the UID and pass it into the logging mechanism.
The work for this is found in overriding the Write method. In that method, the VisitProperties method is used to find the UniqueId property and set that as a property on the backend logger.
protected override void Write(UnsafeString message)
{
try
{
string uniqueId = string.Empty;
var log = ((NLogLoggingTypeSource)TypeSource).Logger;
this.Context.VisitProperties((string name, object value) =>
{
if (name == "UniqueId")
{
if (value != null && !(value is string s && string.IsNullOrEmpty(s)))
{
uniqueId = value.ToString();
}
}
});
log.Properties[Constants.UniqueIdKey] = uniqueId;
}
catch (Exception exception)
{
Debug.WriteLine(exception);
}
base.Write(message);
}
In this code, the VisitProperties looks for the property UniqueId. Recall that this is the name of a property found in the LoggingPropertyData class that was instantiated and assigned in the middleware. If found, it sets the local variable uniqueId to that value. The local variable is then used to set the property on the logger that does the actual logging.
Rendering UniqueId
The final step to this includes writing some code to process the uniqueId value so that it is formatted and then some configuration so that it gets written to the logs. This part isn’t specifically PostSharp related code but it does demonstrate how to take the property value and write it out to the log file without having to copy/paste code everywhere. Other backend logging systems may have ways of accomplishing the same thing but this example does so using NLog.
NLog allows developers to extend the LayoutRenderer class and then override the Append method in order to create a Render item that can be inserted into the nlog config file. In this case, a new LayoutRenderer object is created that is labeled “UniqueId”. In the Append method, a check is made for the uniqueId property in the log event. If found, it is reformatted so that all the “-“ characters are removed providing a single string of 32 characters. If it is not found then the value is padded with all spaces. This is useful when writing to the log file as it creates a more symmetric appearance.
In the NLog config file, the “UniqueId” renderer property can be inserted into any layout where desired. In the case of the trace file, the layout is structured as follows.
layout="${longdate}|${var:threadid}|${UniqueId}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}"
Object Logging
Out of the box, PostSharp will generate logging that will write out the inputs and outputs from methods that are configured to have logging. (Typically public and protected methods but it depends on what is defined in the GlobalAspects file.) However, if an object is being passed in or returned, PostSharp will render the results of the ToString method on that object. Therefore, instead of seeing the data passed in or returned, the class name as rendered in the log message as that is the default behavior for the ToString method. In order to make this more useful, override the ToString method and return the values of the properties in the object. This is very easy to do using JSON serialization of the object.
return JsonConvert.SerializeObject(this);
This is very convenient but be aware that this can expose Personal Identifying Information (PII) data in the log files. This is acceptable in a debug build when developing but not for a release build that will be deployed to a customer’s site. To avoid putting PII data in the log files, clone the object, mask the PII data, and then write it to the log file. Argo uses a NuGet package called ObjectCloner to quickly clone an object. Here is a sample of how that works. In the example, the method ScrubData.Obscure replaces PII data with an asterisk (*).
MyProjectDTO x = this.DeepClone();
x.PIIData = ScrubData.Obscure(x?.PIIData);
return JsonConvert.SerializeObject(x);
Using conditional compile directives, the debug build can render everything while the release build can mask sensitive data.
Conclusion
Argo’s use of PostSharp has proven to be a smart choice. Since that initial POC project, PostSharp has been integrated into several Argo projects. The logs that are being generated have proven useful in determining the state of a service and in troubleshooting problems.
About the author, Randall Woodman
Randall Woodman is a software developer working at Argo Data in Richardson, TX. He is a US Navy Veteran who got his BS degree in Computer Science after leaving the military. He has been developing professionally since 1994 with several companies in the Dallas, TX area. Randall is also an avid gamer with his current favorite games being Forge of Empires and World of Tanks Blitz. | LinkedIn