Logging to Splunk with Winston

I have to admit, I’ve still got a soft spot for Splunk in my heart. I spent several years developing apps there and it is still my go-to logging platform. Recently, I’ve been playing with ExpressJS and using Winston as my logger of choice, together with express-winston to hook the two pieces up. My projects inevitably start with this:

var express = require('express'),
    winston = require('winston'),
    expressLogger = require('express-winston');

var app = express();

app.use(expressLogger.logger({
    transports: [
        new winston.transports.Console()
    ],
    level: 'debug'
}));

// Do other setup here
app.listen(process.env.PORT || 3000);

This is all well and good, but what about Splunk? My prior version of this wrote the log to a file and then Splunk would consume the file. However, I’m operating inside of Azure App Service these days and my Splunk instance is operating on a different machine – it’s a virtual machine inside of Azure. So what am I to do?

Splunk recognized this and so they produced a high-performance HTTP event collector. This is a REST endpoint that allows you to submit data as long as you have a token. I’m not going to explain how to get a token (Splunk does a really good job of that). However, I need to handle the other side of things – the Winston transport.

Fortunately, Winston has a highly extensible transport system and I’ve done just that. You can download the module from npmjs.org or get it from my GitHub repository.

So, how do you use it? It doesn’t require Express, but I’m going to alter my prior example to show how easy it is. Note the highlighted lines:

var express = require('express'),
    winston = require('winston'),
    SplunkStreamEvent = require('winston-splunk-httplogger'),
    expressLogger = require('express-winston');

var app = express();

var splunkSettings = {
    host: 'my-splunk-host',
    token: 'MY-DATAINPUT-TOKEN'
};

app.use(expressLogger.logger({
    transports: [
        new winston.transports.Console(),
        new SplunkStreamEvent({ splunk: splunkSettings });
    ],
    level: 'debug'
}));

// Do other setup here
app.listen(process.env.PORT || 3000);

Block-by-block:

  1. Line 3 brings in the library – standard Node module management here
  2. Lines 8-11 define the options for the splunk-logging library
  3. Line 16 adds the transport to winston for logging

It’s as simple as that. There is one proviso. Underneath, it uses the excellent splunk-logging library. Winston expects that you send off each event individually. It doesn’t really stream events. As a result, setting any of the options in such a way that batching occurs will result in weird errors. That’s because Winston is expecting a callback for each event and the splunk-logging library doesn’t call the callback unless it actually writes to the channel. I haven’t done any high capacity tests to see what happens when batching does occur, so I’d avoid that for now.

If you find any bugs or wish to ask a question, please let me know through the GitHub Repository.

ASP.NET vNext Identity Part 7 – Logging

There are still some rough edges to Visual Studio 2015 CTP 6 and one of the biggest is problems with NuGet packages that don’t conform to newly revised requirements. This isn’t really surprising given that the developers are trying to move to an open source and multi-platform environment. But it’s a little painful.

One of the elements that I was having problems with is logging. Every application of any size needs logging. I could rant for hours on proper logging and how it helps support diagnose problems plus provide meaningful usage statistics and allow you to concentrate development in places that matter. That’s a post for another time.

In order to really implement logging I turn to libraries. Either Log4Net or NLog as the fancy strikes me. Both are open source libraries that are distributed via NuGet. However in both cases there is something in there that Visual Studio 2015 CTP 6 doesn’t like. When you install the library into your project – by editing project.json, using the NuGet Packaging Manager or the Package Manager Console, you will see a little yellow triangle of doom in the references:

blog-code-0408-1

If you go to your error list you will see the following reason:

blog-code-0408-2

I know that once Visual Studio 2015 goes GA this problem will be resolved. It’s just too big to be ignored, even if it’s painful for me now. But I want to continue developing. There are two options:

  1. Write Debug.WriteLine everywhere and integrate the library by editing every file again later
  2. Write a wrapper class for the logging library and use that, then refactor one class later

I like option 2. In my Services directory, I’m going to add a class that implements logging. The below isn’t the entire file – I’ve left only the important bits in:

using System;
using System.Text;

namespace AspNetIdentity.Services
{
    public class Logger
    {
        private string _className;

        /// <summary>
        /// Create a new Logger instance
        /// </summary>
        /// <param name="className"></param>
        public Logger(string className)
        {
            this._className = className;
        }

        #region Logging Methods
        public void Trace(string fmt, params string[] list)
        {
            Log("TRACE", fmt, list);
        }

        // Other logging routines here

        public void Enter(string method, params string[] list)
        {
            var m = new StringBuilder(String.Format("{0}(", method));
            for (int i = 0; i < list.Length; i++)
            {
                if (i != 0) m.Append(",");
                m.Append("\"" + list[i] + "\"");
            }
            m.Append(")");
            Log("ENTER", m.ToString());
        }

        public void Leave(string method)
        {
            Log("LEAVE", method);
        }
        #endregion

        private void Log(string lvl, string fmt, params string[] list)
        {
            string h = String.Format("### {0} [{1}]:", _className, lvl);
            string m = String.Format(fmt, list);
            System.Diagnostics.Debug.WriteLine(h + " " + m);
        }

        public static Logger GetLogger(string className)
        {
            return new Logger(className);
        }
    }
}

Basic functionality is that I create a logger as a static variable at the start of your class and then use it to call .Trace, .Enter, etc. to write logs out. This all consolidates down to using .Log which does a Debug.WriteLine. When I do the refactor for a logging library, this is the only class I have to touch. Everything else just uses this class.

Let’s say I wanted to instrument my EmailService class. At the top of the class I would place the following:

private static Logger logger = Logger.GetLogger(typeof(EmailService).Name);

Then all my Debug.WriteLine calls can be changed to logger.Trace calls.

Even with this (and any other logging library), the Output Debug window is liable to be cluttered. This is, fortunately, easy to fix. Go to the Quick Launch and type in Debug Output. You will see a result Debugging => Output Window. Select that to get something like the below:

blog-code-0408-3

You definitely want to leave All debug output and Exception Messages turned on – those are a vital part of the functionality you need to diagnose issues. However you can probably turn the rest of the entries under the General Output Settings off.

Right now I still get a bunch of Loaded… messages. Still it was less than I was getting before and it allows me to see my tracing messages much more easily.

Want things to improve? Check out this UserVoice suggestion and consider voting for it. While you are there, consider looking at other ideas and voting for the ones you think should be implemented.

In the meantime, I’ve checked in my code and you can check it out at my GitHub Repository.