ASP.NET Core – tracking flow of requests with NLog

2017-02-18 TPodolakASP.NET Core, NLog3 Comments

1. Introduction

A while ago I wrote an article about using MappedDiagnosticsLogicalContext for tracking request flow in your application. As we are moving our project to ASP.NET Core, I wanted to keep that functionality in place. Unfortunately, MDLC layout renderer is not available in that framework anymore(when targeting .NET Core). Luckily, there are two other renderers which can be used as a replacement:

aspnet-traceidentifier
aspnet-item

2. Configuring NLog

Before I dig into details of layout renderers mentioned above, we have to configure ASP.NET Core to use NLog as a logger. First of all, we need to grab NLog.Web.AspNetCore NuGet package. Once the package is installed we have to manually add NLog.config to the project (the file won’t be added automatically by NuGet installer). The next step is to configure NLog with our config, then configure NLogWeb and finally register NLog in LoggingFactory. All of these steps should be done in Startup class.

public class Startup
{
    public Startup(IHostingEnvironment env)
    {
        // rest of the code omitted for brevity
        env.ConfigureNLog("NLog.config");
        // rest of the code omitted for brevity
    }
	
    // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
    public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
    {
        // rest of the code omitted for brevity
        loggerFactory.AddNLog();
        app.AddNLogWeb();
        // rest of the code omitted for brevity
    }
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

public class Startup

{

public Startup(IHostingEnvironment env)

{

// rest of the code omitted for brevity

env.ConfigureNLog("NLog.config");

// rest of the code omitted for brevity

}

// This method gets called by the runtime. Use this method to configure the HTTP request pipeline.

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)

{

// rest of the code omitted for brevity

loggerFactory.AddNLog();

app.AddNLogWeb();

// rest of the code omitted for brevity

}

}

The final step required for NLog to work is to register HttpContextAccessor in IoC container of your choice. If you use the build one, you can do it like that

public class Startup
{
    // rest of the code omitted for brevity
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();
    }
    // rest of the code omitted for brevity
}

1

2

3

4

5

6

7

8

9

public class Startup

{

// rest of the code omitted for brevity

public void ConfigureServices(IServiceCollection services)

{

services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();

}

// rest of the code omitted for brevity

}

3. Using aspnet-traceidentifier renderer

Aspnet-traceidentifier layout renderer allows you to obtain value of TraceIdentifier property from current HttpContext. TraceIdentifier is basically unique id which identifies the request. The renderer can be used as follows

	<?xml version="1.0" encoding="utf-8" ?>
	<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
	      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	      autoReload="true">
	
	  <extensions>
	    <add assembly="NLog.Web.AspNetCore"/>
	  </extensions>
	  
	  <targets>
	    <target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"
	            layout="TimeStamp=${longdate} Level=${uppercase:${level}} TraceId=${aspnet-traceidentifier} Message=${message}" />
	  </targets>
	   
	  <rules>
	    <logger name="*" minlevel="Debug" writeTo="File" />
	  </rules>

</nlog>

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

<?xml version="1.0" encoding="utf-8" ?>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

autoReload="true">

<extensions>

<add assembly="NLog.Web.AspNetCore"/>

</extensions>

<targets>

<target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"

layout="TimeStamp=${longdate} Level=${uppercase:${level}} TraceId=${aspnet-traceidentifier} Message=${message}" />

</targets>

<rules>

<logger name="*" minlevel="Debug" writeTo="File" />

</rules>

</nlog>

From now on (without any additional configuration) every log entry logged (once HttpContext is created), will contain TraceIdentifier.

	TimeStamp=2017-02-15 23:10:52.1901 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values  
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Request successfully matched the route with name '' and template 'api/Values'.
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id 'a133346a-a8f9-4182-ac10-efa1afb18c4d' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'
	TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Get method requested
	TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from thread=4
	TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get, from thread 3 assigned by scheduler
	TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from async continuation, from thread 3
	TimeStamp=2017-02-15 23:10:52.2422 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from explicitly created thread 15
	TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.
	TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=No information found on request to perform content negotiation.
	TimeStamp=2017-02-15 23:10:52.3322 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.
	TimeStamp=2017-02-15 23:10:52.3322 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
	TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 140.4884ms
	TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request finished in 170.7178ms 200 application/json; charset=utf-8
	TimeStamp=2017-02-15 23:10:52.3672 Level=DEBUG TraceId= Message=Connection id "0HL2LTTU1ONI7" completed keep alive response.

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

TimeStamp=2017-02-15 23:10:52.1901 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Request successfully matched the route with name '' and template 'api/Values'.

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id 'a133346a-a8f9-4182-ac10-efa1afb18c4d' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'

TimeStamp=2017-02-15 23:10:52.1941 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Get method requested

TimeStamp=2017-02-15 23:10:52.2091 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from thread=4

TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get, from thread 3 assigned by scheduler

TimeStamp=2017-02-15 23:10:52.2271 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from async continuation, from thread 3

TimeStamp=2017-02-15 23:10:52.2422 Level=INFO TraceId=0HL2LTTU3JVBI Message=Log from Get action, from explicitly created thread 15

TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.

TimeStamp=2017-02-15 23:10:52.3212 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=No information found on request to perform content negotiation.

TimeStamp=2017-02-15 23:10:52.3322 Level=DEBUG TraceId=0HL2LTTU3JVBI Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.

TimeStamp=2017-02-15 23:10:52.3322 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.

TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 140.4884ms

TimeStamp=2017-02-15 23:10:52.3492 Level=INFO TraceId=0HL2LTTU3JVBI Message=Request finished in 170.7178ms 200 application/json; charset=utf-8

TimeStamp=2017-02-15 23:10:52.3672 Level=DEBUG TraceId= Message=Connection id "0HL2LTTU1ONI7" completed keep alive response.

4. Using aspnet-item renderer

If for some reasons we don’t like to use TraceIdentifier as our CorrelationId, we can leverage aspnet-item renderer, which basically allows you to read data from HttpContext.Items collection. However in that case, we are responsible for providing and storing unique identifier of request in HttpContext.Items. Fortunately it is pretty straightforward to do with custom middleware.

public class LoggingMiddleware
{
    private readonly ILogger<LoggingMiddleware> logger;
    private readonly RequestDelegate next;
	
    public LoggingMiddleware(ILogger<LoggingMiddleware> logger, RequestDelegate next)
    {
        this.logger = logger;
        this.next = next;
    }
	
    public async Task Invoke(HttpContext context)
    {
        context.Items["CorrelationId"] = Guid.NewGuid().ToString();
        logger.LogInformation($"About to start {context.Request.Method} {context.Request.GetDisplayUrl()} request");
	
        await next(context);

        logger.LogInformation($"Request completed with status code: {context.Response.StatusCode} ");
    }
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

public class LoggingMiddleware

{

private readonly ILogger<LoggingMiddleware> logger;

private readonly RequestDelegate next;

public LoggingMiddleware(ILogger<LoggingMiddleware> logger, RequestDelegate next)

{

this.logger = logger;

this.next = next;

}

public async Task Invoke(HttpContext context)

{

context.Items["CorrelationId"] = Guid.NewGuid().ToString();

logger.LogInformation($"About to start {context.Request.Method} {context.Request.GetDisplayUrl()} request");

await next(context);

logger.LogInformation($"Request completed with status code: {context.Response.StatusCode} ");

}

}

Of course we have to also use this middleware in our application so we have to add following line

app.UseMiddleware<LoggingMiddleware>();

1	app.UseMiddleware<LoggingMiddleware>();

in configure method of our Startup class. Having all the pieces in place, now we can append CorrelationId read from HttpContext.Items to our log entries with following configuration

	<?xml version="1.0" encoding="utf-8" ?>
	<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
	      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	      autoReload="true">
	
	  <extensions>
	    <add assembly="NLog.Web.AspNetCore"/>
	  </extensions>
	  
	  <targets>
	    <target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"
	            layout="TimeStamp=${longdate} Level=${uppercase:${level}} CorrelationId=${aspnet-item:variable=CorrelationId} Message=${message}" />
	  </targets>
	   
	  <rules>
	    <logger name="*" minlevel="Debug" writeTo="File" />
	  </rules>
	</nlog>

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

<?xml version="1.0" encoding="utf-8" ?>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"

autoReload="true">

<extensions>

<add assembly="NLog.Web.AspNetCore"/>

</extensions>

<targets>

<target xsi:type="File" name="File" fileName="${basedir}/logs/${shortdate}.log"

layout="TimeStamp=${longdate} Level=${uppercase:${level}} CorrelationId=${aspnet-item:variable=CorrelationId} Message=${message}" />

</targets>

<rules>

<logger name="*" minlevel="Debug" writeTo="File" />

</rules>

</nlog>

From now on, CorrelationId will be automatically added to our log entries

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId= Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values  
TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=About to start GET http://localhost:50334/api/values request
TimeStamp=2017-02-15 23:35:56.8333 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request successfully matched the route with name '' and template 'api/Values'.
TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id '5d60d23c-ddef-4d20-98eb-a0c03885bea5' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'
TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)
TimeStamp=2017-02-15 23:35:56.8513 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid
TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Get method requested
TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from thread=3
TimeStamp=2017-02-15 23:35:56.8923 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get, from thread 4 assigned by scheduler
TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from async continuation, from thread 4
TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from explicitly created thread 16
TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.
TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=No information found on request to perform content negotiation.
TimeStamp=2017-02-15 23:35:56.9274 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.
TimeStamp=2017-02-15 23:35:56.9274 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 83.2831ms
TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request completed with status code: 200 
TimeStamp=2017-02-15 23:35:56.9674 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request finished in 134.3253ms 200 application/json; charset=utf-8
TimeStamp=2017-02-15 23:35:56.9764 Level=DEBUG CorrelationId= Message=Connection id "0HL2LUBSKVM2T" completed keep alive response.

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId= Message=Request starting HTTP/1.1 GET http://localhost:50334/api/values

TimeStamp=2017-02-15 23:35:56.8333 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=About to start GET http://localhost:50334/api/values request

TimeStamp=2017-02-15 23:35:56.8333 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request successfully matched the route with name '' and template 'api/Values'.

TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Action 'AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Post (AspNetCoreLoggingWithCorrelationId)' with id '5d60d23c-ddef-4d20-98eb-a0c03885bea5' did not match the constraint 'Microsoft.AspNetCore.Mvc.Internal.HttpMethodActionConstraint'

TimeStamp=2017-02-15 23:35:56.8513 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId)

TimeStamp=2017-02-15 23:35:56.8513 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) with arguments () - ModelState is Valid

TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Get method requested

TimeStamp=2017-02-15 23:35:56.8673 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from thread=3

TimeStamp=2017-02-15 23:35:56.8923 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get, from thread 4 assigned by scheduler

TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from async continuation, from thread 4

TimeStamp=2017-02-15 23:35:56.8993 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Log from Get action, from explicitly created thread 16

TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action method AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId), returned result Microsoft.AspNetCore.Mvc.ObjectResult.

TimeStamp=2017-02-15 23:35:56.9163 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=No information found on request to perform content negotiation.

TimeStamp=2017-02-15 23:35:56.9274 Level=DEBUG CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.JsonOutputFormatter' and content type 'application/json' to write the response.

TimeStamp=2017-02-15 23:35:56.9274 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.

TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Executed action AspNetCoreLoggingWithCorrelationId.Controllers.ValuesController.Get (AspNetCoreLoggingWithCorrelationId) in 83.2831ms

TimeStamp=2017-02-15 23:35:56.9444 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request completed with status code: 200

TimeStamp=2017-02-15 23:35:56.9674 Level=INFO CorrelationId=15989892-9f27-49d0-88b5-ced61b6851ac Message=Request finished in 134.3253ms 200 application/json; charset=utf-8

TimeStamp=2017-02-15 23:35:56.9764 Level=DEBUG CorrelationId= Message=Connection id "0HL2LUBSKVM2T" completed keep alive response.

6. It works in multithreading scenarios

If you take a closer look at logs presented above, you will see that both of the renderers can log proper CorrelationId/TraceId regardless of the thread from which the logger was called. This is possible thanks to implementation of HttpContextAccessor which uses AsyncLocal under the hood, which allows you to persist data across threads.

// decompiled code
namespace Microsoft.AspNetCore.Http
{
    public class HttpContextAccessor : IHttpContextAccessor
    {
        private AsyncLocal<HttpContext> _httpContextCurrent = new AsyncLocal<HttpContext>();
	
        public HttpContext HttpContext
        {
            get
            {
                return this._httpContextCurrent.Value;
            }
            set
            {
                this._httpContextCurrent.Value = value;
            }
        }
    }
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

// decompiled code

namespace Microsoft.AspNetCore.Http

{

public class HttpContextAccessor : IHttpContextAccessor

{

private AsyncLocal<HttpContext> _httpContextCurrent = new AsyncLocal<HttpContext>();

public HttpContext HttpContext

{

get

{

return this._httpContextCurrent.Value;

}

set

{

this._httpContextCurrent.Value = value;

}

}

}

}

Source code for this post can be found here

Boxstarter – breaking infinite reboot loop

2016-12-192016-12-29 TPodolakBoxstarter, PowerShell

1. Introduction

Boxstarter is a great tool for configuring your machine without any user interaction. I’ve been using it for a while now, however recently I’ve noticed that for no apparent reason it wasn’t able to finish the execution of provisioning script as it stuck in infinite reboot loop. Is was quite frustrating for me, that is why I’ve decided to investigate the problem. Here are my findings.

2. Detecting pending reboots

If you dive into Boxstarter source code you will notice that script responsible for checking if reboot is necessary uses Get-PendingReboot cmdlet. By default Boxstarter doesn’t export it, so if you want to see what it does you have to add following line in your Boxstarer script

Import-Module (Join-Path $Boxstarter.BaseDir Boxstarter.Bootstrapper\Get-PendingReboot.ps1) -global -DisableNameChecking

1	Import-Module (Join-Path $Boxstarter.BaseDir Boxstarter.Bootstrapper\Get-PendingReboot.ps1) -global -DisableNameChecking

Calling the Get-PendingReboot cmdlet will give you an information about mandatory reboots. In my case, the output looked as follows

As you can see RebootPending flag is set to true and the reason is that the value of PendingFileRenVal property is not null. Basically, in most of the cases, a restart is indeed required however, some applications leave information about pending reboot in the registry (HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\PendingFileRenameOperations) and operating system (in some cases) never cleans this up.
As a result Get-PendingReboot indicates that reboot is required and Boxstarter falls into infinite restart loop.

3. Fixing the problem

The obvious solution is to remove that value from the registry key manually. However this approach didn’t work for me, basically because the registry value somehow was added at the beginning of execution of my script. That is why, I’ve decided to modify my script and add a function which clears undesirable pending file renames of my choice.

function Clear-Known-Pending-Renames($ignoredRenames){
    $regKey = "HKLM:SYSTEM\CurrentControlSet\Control\Session Manager\"
    $regProperty = "PendingFileRenameOperations"
    $pendingReboot = Get-PendingReboot

    Write-BoxstarterMessage "Current pending reboot $($pendingReboot | Out-String)"
    
    if($pendingReboot.PendFileRename){

        $output = $pendingReboot.PendFileRenVal | %{$_ -split [Environment]::NewLine} | ? { 
            $current = $_
            ![string]::IsNullOrWhiteSpace($current) -and ($ignoredRenames | ? { $current.StartsWith($_)  } ).Length -eq 0 } | Get-Unique

        if($output -eq $null){
            $output = @()
        }
        
        Set-ItemProperty -Path $regKey -Name $regProperty -Value ([string]::Join([Environment]::NewLine, $output))
        Write-BoxstarterMessage "Updated pending reboot $(Get-PendingReboot | Out-String)"
    }
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

function Clear-Known-Pending-Renames($ignoredRenames){

$regKey = "HKLM:SYSTEM\CurrentControlSet\Control\Session Manager\"

$regProperty = "PendingFileRenameOperations"

$pendingReboot = Get-PendingReboot

Write-BoxstarterMessage "Current pending reboot $($pendingReboot | Out-String)"

if($pendingReboot.PendFileRename){

$output = $pendingReboot.PendFileRenVal | %{$_ -split [Environment]::NewLine} | ? {

$current = $_

![string]::IsNullOrWhiteSpace($current) -and ($ignoredRenames | ? { $current.StartsWith($_) } ).Length -eq 0 } | Get-Unique

if($output -eq $null){

$output = @()

}

Set-ItemProperty -Path $regKey -Name $regProperty -Value ([string]::Join([Environment]::NewLine, $output))

Write-BoxstarterMessage "Updated pending reboot $(Get-PendingReboot | Out-String)"

}

}

As you can see I am taking current value of PendingFileRenameOperations and remove the entries which I know that will stay there forever. Calling that function as the very first step of my installation script solved the problem and I was able to successfully restore my machine from Boxstarter script

Entire Boxstarter script can be found here.

Logstash – reading logs from RabbitMQ

2016-11-17 TPodolakElasticsearch, Kibana, Logstash

1. Introduction

In my previous post, I’ve shown how to configure Logstash to parse logs from files. This is pretty useful however if your application is deployed on multiple servers, you usually log to some kind of central log storage – in my case to queue, RabbitMQ to be more specific. In this post, I will show how to configure Logstash so it reads the logs from that queue.

2. Preparing queue

Before we move to Logstash configuration, first of all, we have to prepare RabbitMQ test instance. If you don’t have RabbitMQ yet, go to this website and install the queue. Once installation is done, go to the installation folder (C:\Program Files\RabbitMQ Server\rabbitmq_server-3.6.5\sbin in my case) and run in console

rabbitmq-plugins.bat enable rabbitmq_management

1	rabbitmq-plugins.bat enable rabbitmq_management

This command will prepare RabbitMQ management website, so it will be easier for us to see what is going on in given queue. In the next step, we have to prepare the queue, the logs will be sent to. You can do it via the website we’ve just enabled (http://localhost:15672/) or via RabbitMQ admin console. As I prefer to automate things as much as possible I will do it via command line. What is quite unusual when it comes RabbitMQ CLI is the fact that it is a python script you have to download and run locally (this is not an executable). The script can be found on management site under this address. Once the script is downloaded (in my case it is saved as rabbitmqadmin.py) you can start preparing necessary elements: exchange, queue and the binding.

python rabbitmqadmin.py declare exchange name=logger type=topic -u username -p password

1	python rabbitmqadmin.py declare exchange name=logger type=topic -u username -p password

python rabbitmqadmin.py declare queue  name=MyAppLogginQueue auto_delete=false durable=true -u username -p password

1	python rabbitmqadmin.py declare queue name=MyAppLogginQueue auto_delete=false durable=true -u username -p password

python rabbitmqadmin.py  declare binding source=logger destination=MyAppLogginQueue routing_key=MyApp -u username -p password

1	python rabbitmqadmin.py declare binding source=logger destination=MyAppLogginQueue routing_key=MyApp -u username -p password

As you can see I’ve created exchange called logger which is bound to MyAppLogginQueue queue using MyApp route. This means that every message with topic MyApp sent to logger exchange will be pushed to MyAppLogginQueue .

3. Preparing Logstash

Logstash configuration will be modified version of my previous config. I will just add another input source. Here is a basic usage

input {	
	rabbitmq {
        host => "localhost"
        queue => "MyAppLogginQueue"
        heartbeat => 30
        durable => true
        password => "password"
        user => "username"
    }
}

1

2

3

4

5

6

7

8

9

10

input {

rabbitmq {

host => "localhost"

queue => "MyAppLogginQueue"

heartbeat => 30

durable => true

password => "password"

user => "username"

}

}

As you can see we will be consuming messages from MyAppLogginQueue which is deployed on localhost. For password and user properties use your own credentials. That is basically it, so now it is time to see if everything is working.

4. Testing coniguration

In order to test the configuration you have to run the Elasticsearch, Kibana and use new config for Logstash. I’ve shown how to do it in one of my recent post . For sending messages to the queue I will just use RabbitMQ management website API. The API exposes

api/exchanges/%2F/{exchange_name}/publish

1	api/exchanges/%2F/{exchange_name}/publish

endpoint accepting POST verbs which can be used for publishing messages to given exchange. In my case POST body will look as follows

{
  "vhost": "/",
  "name": "logger",
  "properties": {
    "delivery_mode": 2,
    "headers": {}
  },
  "routing_key": "MyApp",
  "delivery_mode": "2",
  "payload": "TimeStamp=2016-11-01 00:13:01.1669 CorrelationId=77530786-8e6b-45c2-bbc1-31837d911c14 Level=INFO Message=Request completed with status code: 200",
  "headers": {},
  "props": {},
  "payload_encoding": "string"
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

{

"vhost": "/",

"name": "logger",

"properties": {

"delivery_mode": 2,

"headers": {}

},

"routing_key": "MyApp",

"delivery_mode": "2",

"payload": "TimeStamp=2016-11-01 00:13:01.1669 CorrelationId=77530786-8e6b-45c2-bbc1-31837d911c14 Level=INFO Message=Request completed with status code: 200",

"headers": {},

"props": {},

"payload_encoding": "string"

}

and I will be sending it to

http://localhost:15672/api/exchanges/%2F/logger/publish

1	http://localhost:15672/api/exchanges/%2F/logger/publish

Note that I will be sending messages to the exchange, not to the queue itself. The exchange’s responsibility is to route the message to all bound queues. Here is how it looks in practice

As you can see our configuration is valid and messages are shown on Kibana’s dashboard almost in real time.

Full Logstash config can be found here

Logstash – parsing multiline log entries

2016-11-03 TPodolakElasticsearch, Kibana, Logstash

In my previous post I’ve shown how to configure Logstash so that, it would be able to parse the logs in custom format. Configuration presented in that post had one significant drawback – it wasn’t able to parse multiline log entries. This is a rather common scenario, especially when you log exceptions with a stack trace. Log entry, in that case may look as follows

TimeStamp=2016-11-01 02:08:02.9086 CorrelationId=69dd69bb-3457-4440-8f77-88b1fd39255a Level=ERROR Message=System.InvalidOperationException: Operation is not valid due to the current state of the object.
   at AspNetMvcLoggingWithCorrelationId.Controllers.HomeController.<About>d__2.MoveNext() in E:\Tomek\Programowanie\BlogSrc\AspNetMvcLoggingWithCorrelationId\AspNetMvcLoggingWithCorrelationId\Controllers\HomeController.cs:line 24
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Web.Mvc.Async.TaskAsyncActionDescriptor.EndExecute(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass37.<BeginInvokeAsynchronousActionMethod>b__36(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethod(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3d()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass33.<BeginInvokeActionMethodWithFilters>b__32(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c()
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

TimeStamp=2016-11-01 02:08:02.9086 CorrelationId=69dd69bb-3457-4440-8f77-88b1fd39255a Level=ERROR Message=System.InvalidOperationException: Operation is not valid due to the current state of the object.

at AspNetMvcLoggingWithCorrelationId.Controllers.HomeController.<About>d__2.MoveNext() in E:\Tomek\Programowanie\BlogSrc\AspNetMvcLoggingWithCorrelationId\AspNetMvcLoggingWithCorrelationId\Controllers\HomeController.cs:line 24

--- End of stack trace from previous location where exception was thrown ---

at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)

at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

at System.Web.Mvc.Async.TaskAsyncActionDescriptor.EndExecute(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass37.<BeginInvokeAsynchronousActionMethod>b__36(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()

at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethod(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3d()

at System.Web.Mvc.Async.AsyncControllerActionInvoker.AsyncInvocationWithFilters.<>c__DisplayClass46.<InvokeActionMethodFilterAsynchronouslyRecursive>b__3f()

at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass33.<BeginInvokeActionMethodWithFilters>b__32(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.CallEndDelegate(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResultBase`1.End()

at System.Web.Mvc.Async.AsyncControllerActionInvoker.EndInvokeActionMethodWithFilters(IAsyncResult asyncResult)

at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<>c__DisplayClass2b.<BeginInvokeAction>b__1c()

at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)

Parsing these kind of messages using current configuration will result in grok parsing error

and we won’t be able to search against predefined fields. Fortunately Logstash allows you to configure something called input codecs which basically allows you to transform input data into some other form. One of those codes is multiline codec, which is responsible for “merging” multiline logs into one entry.
Here is example of codec configuration

codec => multiline {
                       pattern => "^TimeStamp=%{TIMESTAMP_ISO8601}"
                       negate => true
                       what => "
}

1

2

3

4

5

codec => multiline {

pattern => "^TimeStamp=%{TIMESTAMP_ISO8601}"

negate => true

what => "

}

The code above says that any line not starting with a “TimeStamp=timestamp value” should be merged with the previous line.
Multiline coded can be added to a variety of inputs. Here is how you can apply it to file input

input {
    file {
        path => ["E:/Tomek/Programowanie/BlogSrc/ElasticStackParsingMultilineEntries/logs/*.log"]
        start_position => beginning
        ignore_older => 0
        sincedb_path => "NUL"
        codec => multiline {
                               pattern => "^TimeStamp=%{TIMESTAMP_ISO8601}"
                               negate => true
                               what => "previous"
        }
    }
}

1

2

3

4

5

6

7

8

9

10

11

12

13

input {

file {

path => ["E:/Tomek/Programowanie/BlogSrc/ElasticStackParsingMultilineEntries/logs/*.log"]

start_position => beginning

ignore_older => 0

sincedb_path => "NUL"

codec => multiline {

pattern => "^TimeStamp=%{TIMESTAMP_ISO8601}"

negate => true

what => "previous"

}

}

}

Thanks to that change, Logstash is now able to correctly parse exceptions from our logs.

Source code for this post can be found here

Getting started with Elastic Stack

2016-11-022016-11-02 TPodolakElasticsearch, Kibana, Logstash

1. Introduction

In one of my previous post I’ve shown how to improve logging in an application by tracking the flow of incoming requests. Now it is time to show the basics of Elastic stack to make searching across multiple log files/sources a piece of cake. Elastic stack (previously called ELK stack) is set of three tools which allows you to parse (Logstash), query (Elasticsearch) and visualize (Kibana) logs with ease.

2. Installation

First of all (as usual) we have to get the tools, so go to elastic.co and download apps mentioned before.
These are stand-alone applications so no installation is required. The only requirement is to have JAVA_HOME system variable pointing to your java directory. In my case, this looks as follows

C:\Program Files\Java\jre1.8.0_91\

1	C:\Program Files\Java\jre1.8.0_91\

3. Elasticsearch

Once all three applications are downloaded we can run Elasticsearch (as there is not additional configuration needed for basic usage) instance via an elasticsearch.bat file.

4. Logstash

Having our Elasticsearch instance up and running, now it is time configure Logstash so that it will be able to parse logs.
Configuration provided in next sections will be able to parse logs with the following format

TimeStamp=2016-07-20 21:22:46.0079 CorrelationId=dc665fe7-9734-456a-92ba-3e1b522f5fd4 Level=INFO Message=About to start GET / request

1	TimeStamp=2016-07-20 21:22:46.0079 CorrelationId=dc665fe7-9734-456a-92ba-3e1b522f5fd4 Level=INFO Message=About to start GET / request

4.1. Configuration

Logstash configuration is done via config file in specific format. You can read about that here
The very first step is to define input and output sections

input {
    file {
        path => ["C:/logs/*.log"]
        start_position => beginning
    }
}
output {
    elasticsearch {
        hosts => "localhost:9200"
    }
    stdout {}
}

1

2

3

4

5

6

7

8

9

10

11

12

input {

file {

path => ["C:/logs/*.log"]

start_position => beginning

}

}

output {

elasticsearch {

hosts => "localhost:9200"

}

stdout {}

}

As you can see the logs will be read from C:\logs directory and parsed content will be pushed to Elasticsearch instance and to the console output.
We can verify correctness of configuration calling

logstash.bat -f  "Path\To\Config\File.conf" -t

1	logstash.bat -f "Path\To\Config\File.conf" -t

If you are making your config file for the first time it is good idea to add additional properties to the file section

ignore_older => 0
sincedb_path => "NUL"

1 2	ignore_older => 0 sincedb_path => "NUL"

This will force Logstash to reparse entire file when restarted and will also make sure that older files are not ignored (by default files modified more than 24 hours ago are ignored).

At this point, Logstash can read the log file but it doesn’t do anything special with it. Next step is to configure a pattern which will be used for log parsing. Logstash uses grok for defining the patterns. Long story short it is kind of a regex which can use predefined patterns. The easiest way to play around with it is to use grokconstructor, for list of ready to use patterns take a look at this

For parsing logs shown in previous section I’ve ended up with this grok pattern

TimeStamp=%{TIMESTAMP_ISO8601:logdate} CorrelationId=%{UUID:correlationId} Level=%{LOGLEVEL:logLevel} Message=%{GREEDYDATA:logMessage}

1	TimeStamp=%{TIMESTAMP_ISO8601:logdate} CorrelationId=%{UUID:correlationId} Level=%{LOGLEVEL:logLevel} Message=%{GREEDYDATA:logMessage}

Notice that you are able to give aliases for particular fields, for instance

TimeStamp=%{TIMESTAMP_ISO8601:logdate}

1	TimeStamp=%{TIMESTAMP_ISO8601:logdate}

means that everything that matches TimeStamp=%{TIMESTAMP_ISO8601} will be stored in logdate field.
Having defined our pattern, now we can add it to the config file. After modifications, it looks as follows

input {
    file {
        path => ["C:/logs/*.log"]
        start_position => beginning
    }
}
filter {
    grok {
        match => { "message" => "TimeStamp=%{TIMESTAMP_ISO8601:logdate} CorrelationId=%{UUID:correlationId} Level=%{LOGLEVEL:logLevel} Message=%{GREEDYDATA:logMessage}" }
    }
}
output {
    elasticsearch {
        hosts => "localhost:9200"
    }
    stdout {}
}

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

input {

file {

path => ["C:/logs/*.log"]

start_position => beginning

}

}

filter {

grok {

match => { "message" => "TimeStamp=%{TIMESTAMP_ISO8601:logdate} CorrelationId=%{UUID:correlationId} Level=%{LOGLEVEL:logLevel} Message=%{GREEDYDATA:logMessage}" }

}

}

output {

elasticsearch {

hosts => "localhost:9200"

}

stdout {}

}

Once we run this config and start querying elastic search for list of all indices via

http://localhost:9200/_cat/indices?v

1	http://localhost:9200/_cat/indices?v

we will see that our logs were parsed and stored in index called logstash-2016.10.30

If we now go to

http://localhost:9200/logstash-2016.10.30

1	http://localhost:9200/logstash-2016.10.30

we will be able to see index information

4.2. Fixing the date fields

At this moment there are two main problems with our configuration. First of all, the indices are created based on read time from file. Second of all our logdate field is treated as string.

By default Logstash creates indices based on read time of the source. However in my opinion it is better to create index names based on time given event occurred.
In order to do that, we have to tell the Logstash which field is responsible for holding timestamp. In my case, this field is called logdate. All we have to do is to map this field into field via date filter

date {
        match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]
}

1

2

3

date {

match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]

}

As you can see first argument is a filed name and rest of the arguments (you can specify more) are just date time formats. By default date filter maps a field from the match property into @timestamp field. So the config above equals this one

date {
        match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]
        target => "@timestamp"
}

1

2

3

4

date {

match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]

target => "@timestamp"

}

If we restart Logstash and get the indices, we will see something similar to that

Second problem can be handled in very similar way. We have to add second date filter and select as target longdate field

date {
        match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]
        target => "logdate"
}

1

2

3

4

date {

match => [ "logdate", "yyyy-MM-dd HH:mm:ss.SSSS" ]

target => "logdate"

}

From now on logdate field will be treated as date so we will be able to filter the logs easily with Kibana

5. Running Kibana

Having all the configuration in place now we are ready to run Kibana. As in previous steps, no installation is needed so just run the Kibana.bat file

and go to

http://localhost:5601/

1	http://localhost:5601/

If you run the app for the first time you will be asked to configure the indices. You can use the default parameters and just click “Create” button.
Once the indices are setup you can start writing queries against the logs. By default entire message is searched for the search terms, however the real power comes with queries written against specific fields. For example, you can search for any errors in the application with this simple query

logLevel: (FATAL OR ERROR)

1	logLevel: (FATAL OR ERROR)

Thanks to date type fields, you can combine this query with date range selector and narrow down time to specific values, just like that

logdate:[2016-07-20 TO 2016-10-31] AND logLevel: (FATAL OR ERROR)

1	logdate:[2016-07-20 TO 2016-10-31] AND logLevel: (FATAL OR ERROR)

These are just the basic queries you can run in Kibana, for more advanced scenarios please visit website . I also strongly encourage you guys to take a look at other feature Elastic stack provides. Source code for this post can be found here

PS
Configuration presented in this post will not be able to parse multiline log entries e.g. exceptions. I will show you how to do it in the next post.