Logging in ASP.NET Web API using log4net and Elasticsearch

In any distributed system with multiple services it is essential to implement logging functionality. You want to know how your system behaves and how services performing. And it would be nice to have a convenient way to review and analyze logs. You can filter these logs by different parameters, indentify problems, create charts and dashboards with different metrics or even provide a value for the business analysts and management.

Currently one of the most popular combination of storing and later analyzing logs is Elasticsearch&Kibana.

So we will create a ASP.NET Web Api REST service, install Elasticsearch, put our logs in it withlog4net and then visualize them in Kibana.

Let’s first jump into the installation of Elasticsearch and Kibana.

I will use Windows 7 as an operating system.

Download Elasticsearch.
Download Kibana.
Download service manager NSSM.

Then go to Oracle site, download Java JDK and install it.
After installation add JAVA_HOME as system variable. You can do it by press WinKey+Break -> open Advanced system settings -> Advanced tab -> Environment variables.
The path should be something like this:
JAVA_HOME

1) Install Elasticsearch

Unpack Elasticsearch and install it with command line.
Install_elasticsearch_1

Then run service manager command and set Startup type of service to Automatic.

service_manager

Now you have to run Elasticsearch service using command service start from your command line. So after service is started let’s check if Elasticsearch works. Open http://localhost:9200/ in the browser and you should see JSON response with name, cluster name and version of Elasticsearch.

{
  name: "James Rhodes",
  cluster_name: "elasticsearch",
  version: {
    number: "2.3.3",
    build_hash: "218bdf10790eef486ff2c41a3df5cfa32dadcfde",
    build_timestamp: "2016-05-17T15:40:04Z",
    build_snapshot: false,
    lucene_version: "5.5.0"
  },
  tagline: "You Know, for Search"
}

Now we have Elasticsearch installed, so let’s install the Kibana now

2) Install Kibana

Kibana runs on NodeJS server. So you need to install NodeJS if you don’t have it yet.
Download it from https://nodejs.org/en/download/ and after installation make sure that you set up PATH variable for it. Similar as we have done for Java JDK. Path should be something like C:\Program Files\nodejs.

Check if NodeJS installed correctly by typing command node -v in command line. It should return version number.
node_v

Now unpack Kibana and NSSM.
Install Kibana with NSSM from command line.
nssm_kibana

Now you can see the Kibana service in your windows services list. So you can either to start it manually or from command line: nssm start kibana.
After service is started you should be able to see Kibana web interface on your browser. The default url for Kibana is http://localhost:5601/kibana

3) Create Web API service and configure logging with log4net.

Open Visual Studio and create Web API application(not empty). We have ValuesControllerclass in Controllers folder created by default. Comment out an Authorize attribute from and run the application. We will log data from this ValuesController. Go to the url : http://localhost:your_port/api/values and you should be able to see XML response.

Let’s now add and configure logging in our application. With the Nuget Package Manager install log4stash it is the log4net appender for Elasticsearch. After this we have to create a wrapper around log4net in order to successfully use dependency injection pattern. I created folder Logger and added to it interface ICoreLogger and a wrapper for log4net class CoreLogger.

ICoreLogger.cs: lang=”csharp”]
public interface ICoreLogger
{
void Debug(object message);
void Debug(object message, Exception exception);
void Info(object message);
void Info(object message, Exception exception);
void Warn(object message);
void Warn(object message, Exception exception);
void Error(object message);
void Error(object message, Exception exception);
void Fatal(object message);
void Fatal(object message, Exception exception);
}
[/code]

CoreLogger.cs:

public class CoreLogger : ICoreLogger
{
    private static readonly ILog Log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);
    public void Debug(object message)
    {
        Log.Debug(message);
    }

    public void Debug(object message, Exception exception)
    {
        Log.Debug(message, exception);
    }

    public void Info(object message)
    {
        Log.Info(message);
    }

    public void Info(object message, Exception exception)
    {
        Log.Info(message, exception);
    }

    public void Warn(object message)
    {
        Log.Warn(message);
    }

    public void Warn(object message, Exception exception)
    {
        Log.Warn(message, exception);
    }

    public void Error(object message)
    {
        Log.Error(message);
    }

    public void Error(object message, Exception exception)
    {
        Log.Error(message, exception);
    }

    public void Fatal(object message)
    {
        Log.Fatal(message);
    }

    public void Fatal(object message, Exception exception)
    {
        Log.Fatal(message, exception);
    }
}

Ok, so our logger is set up, now we have to configure log4net in web.config. Add section log4net to configSections:

  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>

Also add FileAppender in log4net section just to make sure that our logging works:

<log4net>
  <appender name="FileAppender" type="log4net.Appender.FileAppender">
    <file name="txtPath" value="logs\taskmanager-log.txt" />
    <appendToFile value="true" />
    <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date %property{processId} %-5level- %message%newline" />
    </layout>
    <filter type="log4net.Filter.LevelRangeFilter">
      <levelMin value="DEBUG" />
      <levelMax value="ERROR" />
    </filter>
  </appender>
  <root>
    <appender-ref ref="FileAppender" />
  </root>
</log4net>

Couple thing are missing though - we need to inject our CoreLogger in constructor of ValuesController and register dependency in container. Install UnityMVCBootstrapper from Nuget Package Manager and Unity.WebApi. Then go to UnityConfig.cs. It is located in App_Start folder. Set it up as following:

public class UnityConfig
{
    #region Unity Container
    private static Lazy<IUnityContainer> _container = new Lazy<IUnityContainer>(() =>
    {
        var container = new UnityContainer();

        RegisterTypes(container);
        return container;
    });

    /// <summary>
    /// Gets the configured Unity container.
    /// </summary>
    public static IUnityContainer GetConfiguredContainer()
    {
        return _container.Value;
    }
    #endregion

    /// <summary>Registers the type mappings with the Unity container.</summary>
    /// <param name="container">The unity container to configure.</param>
    /// <remarks>There is no need to register concrete types such as controllers or API controllers (unless you want to 
    /// change the defaults), as Unity allows resolving a concrete type even if it was not previously registered.</remarks>
    public static void RegisterTypes(IUnityContainer container)
    {
        // NOTE: To load from web.config uncomment the line below. Make sure to add a Microsoft.Practices.Unity.Configuration to the using statements.
        // container.LoadConfiguration();
        container.RegisterType<ICoreLogger, CoreLogger>();
        // TODO: Register your types here
    }
}

No we need to adjust our startup files Global.asax.cs and Startup.cs.
Global.asax.cs:

public class WebApiApplication : System.Web.HttpApplication
{
    protected void Application_Start()
    {
        AreaRegistration.RegisterAllAreas();
        FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
    }
}

Startup.cs:

public partial class Startup
{
    public void Configuration(IAppBuilder app)
    {
        HttpConfiguration config = new HttpConfiguration();

        // register log4net
        XmlConfigurator.Configure();

        // register routes 
        WebApiConfig.Register(config);

        // registering container 
        IUnityContainer container = UnityConfig.GetConfiguredContainer();
        config.DependencyResolver = new Unity.WebApi.UnityDependencyResolver(container);

        // configure log4net variables
        GlobalContext.Properties["processId"] = "LoggerSimple";

        app.UseWebApi(config);
    }
}

Now let's inject our CoreLogger into ValuesController and call logger inside Get method. Your controller should look like this:

public class ValuesController : ApiController
{
    private readonly ICoreLogger _coreLogger;

    public ValuesController(ICoreLogger coreLogger)
    {
        _coreLogger = coreLogger;
    }

    // GET api/values
    public IEnumerable<string> Get()
    {
        _coreLogger.Debug("our log messate");
        return new string[] { "value1", "value2" };
    }
}

Build the application and open in browser http://localhost:your_port/api/values and you should be able to see XML response as before. But for now in the folder where your application is located you should found logs folder with file loggingSample.txt in it. We specified path to it in log4net appender inside a web.config as well as a string conversionPattern of our log message.

We set up logging and made sure that it is working. Now we have to add more graceful way of logging messages in our web api service. In addition we will be handling and logging exceptions.

4) Setting up logging filter and global exception handler.

Create folder filters in our Web API app and add LogFilter class that designed as following:

public class LogFilterAttribute : ActionFilterAttribute
{
    private string _elapsed;

    [Dependency]
    public ICoreLogger Logger { get; set; }

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        var timer = Stopwatch.StartNew();
        actionContext.Request.Properties["logtimer"] = timer;
    }

    /// <summary>
    ///     Occurs after the action method is invoked.
    /// </summary>
    /// <param name="actionExecutedContext">The action executed context.</param>
    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        if (actionExecutedContext.Response != null)
        {
            var timer = ((Stopwatch)actionExecutedContext.Request.Properties["logtimer"]);
            timer.Stop();
            _elapsed = timer.ElapsedMilliseconds.ToString();
            var message = GetMessage(actionExecutedContext);
            Logger.Info(message);
        }
    }

    private string GetMessage(HttpActionExecutedContext actionExecutedContext)
    {
        return new LogMessage
        {
            StatusCode = (int)actionExecutedContext.Response.StatusCode,
            RequestMethod = actionExecutedContext.Request.Method.Method,
            RequestUri = actionExecutedContext.Request.RequestUri.LocalPath,
            Message = actionExecutedContext.Response.StatusCode.ToString(),
            ElapsedMls = _elapsed
        }.ToString();
    }
}

So we will use this attribute to log messages after action executes. The structure of logged message is represented by the class LogMessage. Add it to you Web API project as well:

public class LogMessage
{
    public int StatusCode { get; set; }
    public string RequestMethod { get; set; }
    public string RequestUri { get; set; }
    public string ElapsedMls { get; set; }
    public string Message { get; set; }

    public override string ToString()
    {
        return string.Format("{0} {1} {2} {3} {4}",
                    StatusCode,
                    RequestMethod,
                    RequestUri,
                    ElapsedMls,
                    Message);
    }
}

Now you can mark ValuesController with LogFilter attribute and remove debug message from Get method of this controller.
In order to make LogFilter attribute work you need to create your own filter provider. So lets create our UnityFilterProvider that will get all existed ActionFilter attributes.

public class UnityFilterProvider : IFilterProvider
{
    private IUnityContainer _container;
    private readonly ActionDescriptorFilterProvider _defaultProvider = new ActionDescriptorFilterProvider();

    public UnityFilterProvider(IUnityContainer container)
    {
        _container = container;
    }

    public IEnumerable<FilterInfo> GetFilters(HttpConfiguration configuration, HttpActionDescriptor actionDescriptor)
    {
        var attributes = _defaultProvider.GetFilters(configuration, actionDescriptor).ToList();

        foreach (var attr in attributes)
            _container.BuildUp(attr.Instance.GetType(), attr.Instance);

        return attributes;
    }
}

Then configure Web API to use our filter provider. Create Extensions class that will contain method RegisterFilters. This method will register our UnityFilterProvider

public static class Extensions
{
    public static void RegisterFilters(this HttpConfiguration config, IUnityContainer container)
    {
        var providers = config.Services.GetFilterProviders().ToList();
        var defaultprovider = providers.Single(i => i is ActionDescriptorFilterProvider);
        config.Services.Remove(typeof(IFilterProvider), defaultprovider);
        config.Services.Add(typeof(IFilterProvider), new UnityFilterProvider(container));
    }
}

The last step for this is to add following line to our Startup.cs Configuration method:

// register filters
config.RegisterFilters(container);

Run the application and you will be able to see in log file something like:
2016-06-08 11:11:51,350 LoggerSample INFO - 200 GET /api/values 49 OK

Ok, let's now create a GlobalExceptionHandler and in order to catch and log our exceptions in one place and then return ErrorResult message.

public class GlobalExceptionHandler : ExceptionHandler
{
    private readonly ICoreLogger _logger;

    public GlobalExceptionHandler(ICoreLogger logger)
    {
        _logger = logger;
    }

    public override void Handle(ExceptionHandlerContext context)
    {
        var timer = ((Stopwatch)context.Request.Properties["logtimer"]);
        timer.Stop();

        var exception = context.Exception;
        var httpException = exception as HttpException;
        var logMessage = new LogMessage
        {
            RequestUri = context.Request.RequestUri.LocalPath,
            RequestMethod = context.Request.Method.Method,
            ElapsedMls = timer.ElapsedMilliseconds.ToString()
        };
        if (httpException != null)
        {
            context.Result = new ErrorResultMessage(context.Request,
            (HttpStatusCode)httpException.GetHttpCode(), httpException.Message);
            return;
        }

        logMessage.Message = exception.StackTrace;
        logMessage.StatusCode = (int)HttpStatusCode.InternalServerError;
        _logger.Error(logMessage.ToString());

        context.Result = new ErrorResultMessage(context.Request, HttpStatusCode.InternalServerError,
        exception.Message);
    }
}
public class ErrorResultMessage : IHttpActionResult
{
    private readonly string _errorMessage;
    private readonly HttpRequestMessage _requestMessage;
    private readonly HttpStatusCode _statusCode;
    public ErrorResultMessage(HttpRequestMessage requestMessage, HttpStatusCode statusCode,
    string errorMessage)
    {
        _requestMessage = requestMessage;
        _statusCode = statusCode;
        _errorMessage = errorMessage;
    }
    public Task<HttpResponseMessage> ExecuteAsync(CancellationToken cancellationToken)
    {
        return Task.FromResult(_requestMessage.CreateErrorResponse(_statusCode, _errorMessage));
    }
}

After we create these classes register GlobalExtensionHandler in Web API application. Add to our Extensions.cs new extension method RegisterGlobalExceptionHandler:

public static void RegisterGlobalExceptionHandler(this HttpConfiguration config, IUnityContainer container)
{
    config.Services.Replace(typeof(IExceptionHandler), new GlobalExceptionHandler(container.Resolve<ICoreLogger>()));
}

and use it Startup.cs Configuration method. The last step inValuesController.Get method put throw some exception before return clause. For example throw new NotImplementedException();. Run application and you will see that in our log file we logged exception and the information about request.

5) Log data into ElasticSearch

The last piece of this article is to log our data directly to ElasticSearch. To do this we need to add log4stash log4net appender into our Web.config file. Place it right after FileAppender:

<appender name="ElasticSearchAppender" type="log4net.ElasticSearch.ElasticSearchAppender, log4stash">
  <Server>localhost</Server>
  <Port>9200</Port>
  <IndexName>logging-sample</IndexName>
  <ElasticFilters>
    <Filter type="log4net.ElasticSearch.Filters.RenameKeyFilter, log4stash">
      <Key>processId</Key>
      <RenameTo>ServiceName</RenameTo>
    </Filter>
    <Filter type="log4net.ElasticSearch.Filters.RenameKeyFilter, log4stash">
      <Key>Message</Key>
      <RenameTo>message</RenameTo>
    </Filter>
    <Grok>
      <SourceKey>message</SourceKey>
      <Pattern>%{NUMBER:ResponseCode} %{WORD:Method} %{URIPATHPARAM:Url} %{NUMBER:ElapsedMls} %{GREEDYDATA:StatusMessage}</Pattern>
    </Grok>
  </ElasticFilters>
  <filter type="log4net.Filter.LevelRangeFilter">
    <levelMin value="INFO" />
    <levelMax value="ERROR" />
  </filter>
</appender>

and add it to the root element:

<root>
  <appender-ref ref="FileAppender" />
  <appender-ref ref="ElasticSearchAppender" />
</root>

That's it!.

Run the application and go to ValuesController. Hit F5 couple of times and then go to http://localhost:9200/logging-sample/_count. You should be able to see count property > 0. That means that we successfully logged data into Elasticsearch. Now you can configure index pattern in kibana and analyze your data.

The source code of the project : https://github.com/singed/LoggingSample

Share this post:Tweet about this on TwitterShare on Facebook0Share on LinkedIn0Share on Google+0Share on Reddit0Email this to someoneDigg this