Monthly Archives: July 2016

Creating a TopShelf application

What is Topshelf?

Topshelf is basically a framework for creating a Windows service (it also supports Mono on Linux – although I’ve not tested this yet).

You might still ask “why do we need this, writing a Windows service isn’t difficult?”

Well a few years back I wrote a similar library, my reasoning was that I wanted to write an application which could be run as both a console application and/or as a Windows service – well Topshelf gives you this capability and more. Ofcourse, it’s also far simpler to debug a console application than a Window’s service.

Getting started

We can write our service in such a way as to have a dependency upon Topshelf or no dependency in which case we use Topshelf methods to redirect Topshelf methods to our code – let’s start by looking at this route (i.e. a non-dependency version of the service).

Topshelf has a perfectly good sample for getting started on their site’s Show me the code page.

I’m going to pretty much recreate it here, but do check out their page.

  • Create a console application (mine’s called MyTickerService)
  • Add a reference to Topshelf via Nuget
  • Create a new class called TickerService

TickerService looks like this

public class TickerService
{
   private readonly Timer timer;

   public TickerService()
   {
      timer = new Timer(5000) {AutoReset = true};
      timer.Elapsed += (sender, e) =>
      {
         Console.WriteLine("Tick:" + DateTime.Now.ToLongTimeString());
      };
   }
 
   public void Start()
   {
      Console.WriteLine("Service started");
      timer.Start();
   }

   public void Stop()
   {
      Console.WriteLine("Service stopped");
      timer.Stop();
   }
}

This is simple enough, we’re just going to keep writing out to the Console on each elaspe of the timer. The Start and Stop methods are there to just allow us to intercept the service start and then the top to allow us to set-up and clean-up anything on our service. The names can be anything we like at this point, as these will ultimately be called from the Topshelf framework methods when we write that code, which we shall do now…

We now need to edit the Program.cs file Main method. Here’s the code

static void Main(string[] args)
{
   HostFactory.Run(x =>
   {
      x.Service<TickerService>(s =>
      {
         s.ConstructUsing(name => new TickerService());
         s.WhenStarted(svc => svc.Start());
         s.WhenStopped(svc => svc.Stop());
      });

      x.SetServiceName("SampleService");
      x.SetDisplayName("Sample");
      x.SetDescription("Sample");
      x.RunAsLocalSystem();
   });
}

Now the Topshelf fluent interface allows us to run the service and as can be seen, when the service starts or stops we simply call any appropriate methods on the TickerService. We then go on to set the service name and the service’s display name and a description before the call to RunAsLocalSystem. We can also run as a specific user/password using RunAs, require a prompt for the same using RunAsPrompt and more (see Topshelf Configuration for more information).

If you now run this application via Visual Studio or from the command prompt, you’ll see the application output text on each elapsed tick. So we can now use our “service” as a standalone console application and debug it easily like this. Then if we want to use the application in a Windows service scenario we can simply run a command prompt as administrator and then use any/all of the following to install the service (once installed it will be visible in services.msc), start the service manually, stop it and uninstall it.

MyTickerService.exe install
MyTickerService.exe start
MyTickerService.exe stop
MyTickerService.exe uninstall

Alternate implementation

The sample code previously showed a way to take a standard C# class and using the Topshelf methods, turn it into a simple service. The class itself had no dependency on Topshelf, but we could have gone a different route and implemented the ServiceControl interface from Topshelf, giving us a TickerService which looks like this

public class TickerService : ServiceControl
{
   private readonly Timer timer;

   public TickerService()
   {
      timer = new Timer(5000) {AutoReset = true};
      timer.Elapsed += (sender, e) =>
      {
         Console.WriteLine("Tick:" + DateTime.Now.ToLongTimeString());
      };
   }

   public bool Start(HostControl hostControl)
   {
      Console.WriteLine("Service started");

      timer.Start();
      return true;
   }

   public bool Stop(HostControl hostControl)
   {
      Console.WriteLine("Service stopped");

      timer.Stop();
      return true;
   }
}

So the only changes here are that we implement the ServiceControl interface and with that implement the Start and Stop methods, meaning we no longer need to tell Topshelf which methods to run when the applications starts and stops, so our Program.cs Main method can now be reduced to

HostFactory.Run(x =>
{
   x.Service<TickerService>();

   x.SetServiceName("SampleService");
   x.SetDisplayName("Sample");
   x.SetDescription("Sample");
   x.RunAsLocalSystem();
});

As our TickerService constructor takes no arguments we can simply use the x.Service() call to create it.

Logging

By default Topshelf will log using TraceSource, but if you want to use one of the alternate, more advanced logging libraries such as NLog or log4net etc. Then thankfully Topshelf allows us to easily integrate these.

I’m going to use NLog. So from Nuget find a version of Topshelf.NLog comaptible with the version of Topshelf you’re using and add this package to your project.

Let’s add a fairly generic NLog configuration to the App.config

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>
  <nlog>
    <targets>
      <target name="console" type="Console" layout="${message}" />
      <target name="debugger" type="Debugger" layout="${message}"/>
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" writeTo="console,debugger" />
    </rules>
  </nlog>
</configuration>

Now we’ll declare the following variable in the TickerService class

private readonly LogWriter logWriter;

within the TickerService constructor, assign the log writer thus

logWriter = HostLogger.Get<TickerService>();

and finally, in place of the Console.WriteLine in the TickerService we use logWriter.Debug for example, here’s the Elasped event

logWriter.Debug("Tick:" + DateTime.Now.ToLongTimeString());

Structured logging with Serilog

Having used several .NET logging frameworks over the years, including the Logging Application Block, log4net, NLog as well as having used various logging frameworks in other languages.

In most cases the output to a log file is a formatted string, but in the past I’ve wondered about creating my logs in a way that could be queried or grouped in a more effective way. Recently this has become more relevant with a work project where we’re starting to use the ELK stack (Elasticsearch, Logstash & Kibana).

So I decided to take a look at some of the structured logging frameworks out there for .NET.

Getting started

I’m using Serilog 2.0, so obviously things may differ from his post with the version you’re using.

Let’s create a very simply console project to try this out on

  • Create a Console application
  • Using NuGet add Serilog
  • Using NuGet add Serilog.Sinks.RollingFile
  • Using NuGet add Serilog.Sinks.Literate

Now, we’ll jump straight into the code for this example

static void Main(string[] args)
{
   Log.Logger = new LoggerConfiguration()
      .WriteTo.LiterateConsole()
      .WriteTo.RollingFile("logs\\sample-{Date}.txt")
      .MinimumLevel.Verbose()
      .CreateLogger();

   Log.Logger.Information("Application Started");

   for (int i = 0; i < 10; i++)
   {
      Log.Logger.Information("Iteration {I}", i);
   }

   Log.Logger.Information("Exiting Application");
}

In this example, we use Serilog’s fluent interface to create our configuration. Whilst Serilog can be configured via a configuration file it appears it’s positioned more towards code based configuration.

Using the WriteTo property we can set-up one or more output mechanisms. In this case I’m using a console (LiterateConsole outputs nice coloured logs to the console), a RollingFile is created in the application’s folder off of the logs folder.

By default, Serilog sets it’s minimum logging level to Information, I’ve effectively told it to log everything by setting it to Verbose in the above code.

If we run this and view the output and/or log file, we’ll find the following output

2016-07-07 15:34:07.864 +01:00 [Information] Application Started
2016-07-07 15:34:07.906 +01:00 [Information] Iteration 0
2016-07-07 15:34:07.908 +01:00 [Information] Iteration 1
2016-07-07 15:34:07.908 +01:00 [Information] Iteration 2
2016-07-07 15:34:07.909 +01:00 [Information] Iteration 3
2016-07-07 15:34:07.910 +01:00 [Information] Iteration 4
2016-07-07 15:34:07.911 +01:00 [Information] Iteration 5
2016-07-07 15:34:07.911 +01:00 [Information] Iteration 6
2016-07-07 15:34:07.912 +01:00 [Information] Iteration 7
2016-07-07 15:34:07.912 +01:00 [Information] Iteration 8
2016-07-07 15:34:07.913 +01:00 [Information] Iteration 9
2016-07-07 15:34:07.913 +01:00 [Information] Exiting Application

As our purpose was to get queryable output, this doesn’t really help a lot, what we really want is a more structured format of output, like XML or JSON.

Let’s replace the .WriteTo.RollingFile line with the following

.WriteTo.Sink(new
   RollingFileSink("logs\\sample-{Date}.txt",
      new JsonFormatter(renderMessage: true), 1073741824, 31))

Now our log file output looks like this

{"Timestamp":"2016-07-07T15:42:35.2095535+01:00","Level":"Information","MessageTemplate":"Application Started","RenderedMessage":"Application Started"}
{"Timestamp":"2016-07-07T15:42:35.2695595+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 0","Properties":{"I":0}}
{"Timestamp":"2016-07-07T15:42:35.2725598+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 1","Properties":{"I":1}}
{"Timestamp":"2016-07-07T15:42:35.2735599+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 2","Properties":{"I":2}}
{"Timestamp":"2016-07-07T15:42:35.2735599+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 3","Properties":{"I":3}}
{"Timestamp":"2016-07-07T15:42:35.2745600+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 4","Properties":{"I":4}}
{"Timestamp":"2016-07-07T15:42:35.2745600+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 5","Properties":{"I":5}}
{"Timestamp":"2016-07-07T15:42:35.2755601+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 6","Properties":{"I":6}}
{"Timestamp":"2016-07-07T15:42:35.2755601+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 7","Properties":{"I":7}}
{"Timestamp":"2016-07-07T15:42:35.2765602+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 8","Properties":{"I":8}}
{"Timestamp":"2016-07-07T15:42:35.2765602+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 9","Properties":{"I":9}}
{"Timestamp":"2016-07-07T15:42:35.2775603+01:00","Level":"Information","MessageTemplate":"Exiting Application","RenderedMessage":"Exiting Application"}

We now have Json output – which I’m sure was obvious by the use of the JsonFormatter. The use of renderMessage : true (the default for this is false) ensures the output includes the rendered message as well as the MessageTemplate etc. The rendered message is equivalent to what the textual output would be.

Returning to our original code (the Main method) we have the following Log.Logger.Information(“Iteration {I}”, i);. You’ll notice we are using the placeholder {} syntax. The “I” within the {} could be named anything you want. It’s basically the property name uses in the Json Properties field. Ofcourse we can just as easily change this to something a little more meaningful such as

Log.Logger.Information("Iteration {Iteration}", i);

What is important though is to not fall into the trap of using a String.Format for this as this would lose the Iteration property name.

Adding context

Often we’ll want to log with some more context, for example what class we’re logging from, especially in situations where we might have similar output messages throughout our code. In such cases we can use the ForContext method

Log.Logger.ForContext<Program>().Information("Application Started");

this will cause our log file output to include the property SourceContext which a value of the namespace.classname for example

"Properties":{"Iteration":9,"SourceContext":"SerilogTest.Program"

Note: You might prefer to store the ILogger returned by Log.Logger.ForContext() instead of having the long line of code every time.

Clean disposal/completion of logging

Depending upon the logging mechanism used within Serilog, you may need to call the following when your application shutsdown

Log.CloseAndFlush();

this is especially relevent if the logging mechanism is buffered.

That’s it – straightforward, easy to use and now we can read the Json log files into some appropriately capable application and query or group etc. our log entries.