Know the heartbeat and soul of your applications and services

This year I built a few systems that are defined by many as microservices. These services are independent by how they scale, perform and by what they do. The services can be built on any technology and be deployed using Docker containers, Nugetpackages, NPM, FTP, file drops and more. It really doesn’t matter as long as it makes sense. My services often communicate over TCP using HTTP or WebSockets. What I want next is to get an understanding of the application and service state and be able to choose and configure how deep that data is reflecting the application core. That could be errors, communications faults, successful transactions, pull frequencies from databases and other sources, business KPIs. Really everything. This state and heartbeat can be used to trace and monitor the state close to real-time. This can also be a supplement to your existing data warehouse and business intelligence, as well as making a foundation to understand how your own code works.

With my distributed services running in the cloud or on-premise, it can also be a very tedious task to dissect and debug these services and the system as a whole. My system can sometimes feel like the image above. I have some components that I believe is what it is, but I am not sure it always reflects the real world. When a single message flows through multiple layers in a single application in a multithreaded environment it is difficult enough to follow that single message. When 100 000 messages flow through multithreaded applications or services at the rate of 100 000 messages each second, it makes it impossible for the human mind to fully understand just from watching the codebase. The system has become a beast with its own heartbeat and soul, and it really does not require much code to create such as beast with all those messages available in this era of Internet of Things. As developers and architects, we need a new approach from the beginning. It is time to bring modern logging tools  into the picture.

I have the privilege to know and work with Vagif Abilov (@ooobject). And if it is one thing I learned that changed the way I develop and do architecture in my applications, it is logging with Serilog and using the ELK (Elasticsearch, Logstash (some use NXLog instead) and Kibana) stack from day one.

How to log using Serilog (C# sample)

Serilog is built to structure event data and feed it to the target of choice. These targets are called sinks. A list of sinks and targets can be found on a Serilog Github page and some of the targets are:

• Amazon Kinesis
• Application Insights
• Azure DocumentDB
• Azure Event Hubs
• Azure Table Storage
• CouchDB
• CouchBase
• DataDog
• Elasticsearch
• elmah.io
• Email
• Exceptionless
• SQL Server
• ++

To configure Serilog in a.NET application I configure Serilog like this:

-Bilde

This code is often put in my Global.asax or Program.cs file, or some other starting point of my .NET application. The config is set up to write to .txt files on the local disk of that service. It writes the file in the format of “Log-20160118.txt“. It is a rolling file sink so it changes to a new file every day, and it is configured to hold 5 days retention of those log files. Serilog removes the expired files. I use a JsonFormater in the sink to have the output formatted as JSON. This makes the log entry very useful as it will be generated with properties and depth. Enrichers is a great thing I will blog about in the future. For now I can tell you, enrichers make logging easier. Having global enrichers, like those above, attaches the machine name to every log entry I make in the application, and also adds the source name and enables a log context functionality that makes it possible to wrap every log entry in a code execution block with a property.

If I would like to create a log entry using C# I could write it like this:

• The above log entry is logged as Information level.
  • Most common is Debug, Information, Warning, and Error.
• The first parameter in the log (“GetCustomerPurchaseFile”) entry is a text field. It is a template that can contain any text and Serilog properties.
  • Properties are usually defined using {myProperty} and using @ property inside the curly brackets {@myProperty} will serialize the property instead of stringifying it. This makes it possible to attach an object or a tree of objects that will be serialized into the log. Be careful here on what you actually include. Using Destructurama you can annotate the properties you don’t want as a part of the log entry to reduce log size.
  • The property definitions can be named anything in the template because they don’t refer to the property name, but the order of the following parameters is the order they are written to the log entry.

This is the result of the log entry above:

• We can see the enrichers and Serilog adding more properties to the log entry once it is written to file.
  • TimeStamp, Level, MachineName, Source.

The log files

Logging with Serilog as I explained above, I get files that contain a large number log entries. They can easily grow to several gigabytes each day. It makes the log entries quite hard to read and navigate through, and in many ways useless unless you know exactly what you are looking for. The logs are now distributed only, but they have a few things in common. They are all logged as JSON and they all have a timestamp and they share some common properties that can be quite interesting to look at once we put it all together.