Loglama Yapılarında Correlation ID ile Traceability’i Sağlamak

Merhaba arkadaşlar.

Bu makale konusunda sizlerle uygulamalarımızda Correlation ID aracılığı ile consistent bir şekilde nasıl log’lama işlemlerini gerçekleştirebiliriz konusunu ele almaya çalışacağım.

Çoğu zaman geliştirmekte olduğumuz uygulamalarda, arkaplanda neyin olup bittiğini anlayabilmek için genelde çeşitli log’lama işlemlerini gerçekleştiririz. Özellikle büyümekte ve büyük çapta olan projelerde, monolithic architecture’ların yerine distributed architecture’ların tercih edilmesiyle beraber, distributed dünya sağlamış olduğu bir çok faydanın yanında business process yönetimi ve consistency gibi bazı sorunları da beraberinde getirmektedir.

Senaryo

Yukarıda ki gibi bir örnekle açıklamak gerekirse eğer:

Örneğin X request’i ilgili business işlemini gerçekleştirebilmesi için, -n tane service ile çalışması gerekmektedir. Gerçekleştirecek olduğu bu service call’lar sonucunda ise, oluşturacağı bir result bulunmaktadır.

Peki, bu service call’ları sırasında herhangi bir noktada kopma/network split yaşanırsa? Hangi log işlemi, hangi request içerisinde gerçekleşti? İşte bu gibi problemlerde Correlation ID yaklaşımı imdadımıza koşmaktadır.

Yaklaşım

Service’ler arasında her bir request için unique identifier görevini görecek olan bir Correlation ID gezdirilir. Bu sayede hangi request hangi koşullarda ve nasıl hata alındığının log’larını takip edebilmek, oldukça kolaylaşacaktır.

Distributed yaklaşımların dışında bazı durumlarda ise uygulamalarımızda ki bottleneck’leri ortaya koyabilmek için farklı senaryolarda test case’leri ve log işlemleri gerçekleştiririz.

Örneğin X request’i, ilgili result set’i oluşturabilmek için hangi business process’lerden/gateway’lerden geçiyor? Hangi parametreler ile ilerliyor? Nerede ne kadar vakit harcıyor?

Bunlar gibi soruları cevaplayabilmek için, log’lama işlemini gerçekleştirirken Correlation ID çözümü ile ilerleyebiliriz. Bu sayede istediğimiz contextual bilgileri log’larken, Correlation ID ile de log’lamadaki traceability’i arttırarak, bottleneck’leri hızlı bir şekilde ortaya koyabiliriz.

[Info:Entering] CorrelationID:12345 10/16/2016 10:05:45.125 FooNamespace.FooClass.FooMethod<T>, "Parameter_1", "Parameter_2"
[Info:Executing] CorrelationID:12345 10/16/2016 10:05:58.95 FooNamespace.FooClass.FooMethod<T>, "Parameter_1", "Parameter_2"
[Info:Leaving] CorrelationID:12345 10/16/2016 10:06:20.45 FooNamespace.FooClass.FooMethod<T>, "Parameter_1", "Parameter_2"

Loglama

Gerçekleştireceğimiz örnekte log’lama için NLog kütüphanesini kullanacağım. Loglama yaparken herhangi bir aspect kütüphanesi kullanmayacağım. Sizler dilerseniz lisanslı olarak PostSharp veya open-source olarak Fody gibi kütüphaneler aracılığı ile intercept işlemlerini gerçekleştirerek log’lamaları yapabilirsiniz.

“LogTraceWithCorrelationId” isminde yeni bir console application oluşturalım. İçerisine aşağıdaki resimde olduğu gibi NuGet üzerinden “NLog” ve “NLog.Config” kütüphanelerini kuralım.

Kütüphanelerin kurulumu ardından öncelikle “NLog.config” dosyasını aşağıdaki gibi düzenleyelim.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      throwExceptions="true"
      internalLogLevel="Trace"
      internalLogFile="..\..\..\Logs\nlog-app.log">
  <targets>
    <!-- database -->
    <target name="database" xsi:type="Database" keepConnection="true" useTransactions="true"
             dbProvider="System.Data.SqlClient"
             connectionString="data source=.;initial catalog=TestDb;integrated security=true;"
              commandText="INSERT INTO Logs(EventDateTime, EventLevel, CorrelationId, MachineName, EventMessage, ErrorSource, ErrorClass, ErrorMethod, ErrorMessage, InnerErrorMessage) VALUES (@EventDateTime, @EventLevel, @CorrelationId, @MachineName, @EventMessage, @ErrorSource, @ErrorClass, @ErrorMethod, @ErrorMessage, @InnerErrorMessage)">

      <!-- parameters for the command -->
      <parameter name="@EventDateTime" layout="${date:s}" />
      <parameter name="@EventLevel" layout="${level}" />
      <parameter name="@CorrelationId" layout="${activityid}"/>
      <parameter name="@MachineName" layout="${machinename}" />
      <parameter name="@EventMessage" layout="${message}" />
      <parameter name="@ErrorSource" layout="${event-context:item=error-source}" />
      <parameter name="@ErrorClass" layout="${event-context:item=error-class}" />
      <parameter name="@ErrorMethod" layout="${event-context:item=error-method}" />
      <parameter name="@ErrorMessage" layout="${event-context:item=error-message}" />
      <parameter name="@InnerErrorMessage" layout="${event-context:item=inner-error-message}" />
    </target>
  </targets>
  <rules>
    <!-- logging rules here -->
    <logger name="*" minlevel="Debug" writeTo="database" />
  </rules>
</nlog>

Bu config dosyası ile log’ların database’e kaydedilmesi gerektiğini, parameter’lar ile de “commandText” üzerindeki parametreleri set ediyoruz. “rules” kısmında ise “minlevel” parametresi ile “debug” seviyesinde log’lanmasını ve target olarak da “database” target’ını kullanmasını söylüyoruz.

NLog başlıca aşağıdaki log level’larını desteklemektedir:

• Trace: bu level genelde development sırasında detaylı olarak hight-volume bilgilere erişebilmek için kullanılmaktadır.
• Debug: bu level’da production ortamında kullanılmaz ve trace level’ından daha az bilgi içermektedir.
• Info: genelde information bilgileri için kullanılır ve production ortamlarında da kullanılabilinir.

Bize örneğimizde debug level’ı yeterli olacaktır.

Config dosyasının ayarlanması ardından yukarıdaki parametrelere denk gelecek olan SQL tablosunu da aşağıdaki script ile oluşturalım.

CREATE TABLE [dbo].[Logs](
	[Id] [int] IDENTITY(1,1) NOT NULL,
	[EventDateTime] [datetime] NOT NULL,
	[EventLevel] [nvarchar](100) NOT NULL,
	[CorrelationId] [uniqueidentifier] NOT NULL,
	[MachineName] [nvarchar](100) NOT NULL,
	[EventMessage] [nvarchar](max) NOT NULL,
	[ErrorSource] [nvarchar](100) NULL,
	[ErrorClass] [nvarchar](500) NULL,
	[ErrorMethod] [nvarchar](max) NULL,
	[ErrorMessage] [nvarchar](max) NULL,
	[InnerErrorMessage] [nvarchar](max) NULL,
 CONSTRAINT [PK_Logs] PRIMARY KEY CLUSTERED 
(
	[Id] ASC
)WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, 
 ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]

Tablo field’larına dikkat ettiyseniz “CorrelationId” field’ı dışındakiler, NLog‘un sahip olduğu default field’lardır. Bu bölümde ise “CorrelationId” field’ını nasıl kullanabileceğimize bakacağız.

NLog‘un 4.1 versiyonundan sonra “${activityid}” parametresi ile, log mesajlarını trace edebilmek için correlation id desteği getirilmiştir. Bundan önceki versiyonlarında ise bu tarz bir işlemler için custom olarak bir layout renderer yazmak gerekiyordu.

Not: NLog‘un ${activityid} parametresi correlation id’yi “System.Diagnostics” namespace’i altında bulunan, “Trace.CorrelationManager.ActivityId” property’sinden okumaktadır.

Log kütüphanesi hazır olduğuna göre “Program.cs” i açalım ve aşağıdaki gibi kodlayalım.

using System;
using NLog;

namespace LogTraceWithCorrelationId
{
    class Program
    {
        private static Logger _logger = LogManager.GetCurrentClassLogger();

        static void Main(string[] args)
        {
            //Per request
            System.Diagnostics.Trace.CorrelationManager.ActivityId = Guid.NewGuid();

            DoWork();
        }

        private static void DoWork()
        {
            //...

            _logger.Debug("DoWork method'u çalıştırıldı.");

            DoOtherWork();
        }

        private static void DoOtherWork()
        {
            //...

            _logger.Debug("DoOtherWork method'u çalıştırıldı.");
        }
    }
}

Dikkat edersek iç içe sequentially olarak ilerleyen 2 adet method bulunmakta.

“Main” method’u içerisinde “System.Diagnostics.Trace.CorrelationManager.ActivityId” property’sine yeni bir guid set ediyoruz. Ardından ilk method olan “DoWork” method’unu call ediyoruz. Method’lar içerisinde ise “LogManager.GetCurrentClassLogger” method’u ile elde etmiş olduğumuz NLog instance’ı üzerinden, “Debug” method’unu kullanarak bir log mesajı atıyoruz.

NLog bu işlemlerin ardından bu process bitene kadar set etmiş olduğumuz “ActivityId” parametresini, otomatik olarak log’lar arasında taşıyacaktır. Bu sayede herhangi bir process/request için tüm akışı trace edebilmek kolay bir hale gelecektir.

Yukarıdaki console uygulamasını çalıştıralım ve çıktısına SQL Server Management Studio üzerinden bir bakalım.

Gördüğümüz gibi atmış olduğumuz 2 adet “Debug” log’unu, CorrelationId’leri ile birlikte SQL üzerine insert etmiş durumdadır.

Burada log’lamak istediğiniz parametreleri, ilgili business value’larınıza göre sizler belirleyebilirsiniz.

Main method’unda set etmiş olduğumuz “ActivityId” parametresini, web ortamında ise handler’lar aracılığı ile “BeginRequest” event’larında request header’ına set edebilirsiniz.

Her ne kadar basit bir konu gibi görünse de, birçok case karşısında oldukça fayda sağlamaktadır/sağlayacaktır.

Bu makalede sizlere Correlation ID kullanımının, özellikle distributed ortamlarda önemini anlatabilmeye/aktarabilmeye çalıştım. Sizlerde içerisinde bulunduğunuz ortamlarda, farklı kütüphaneler aracılığı ile bu işlemi gerçekleştirebilirsiniz.

Umarım faydalı bir yazı olmuştur. Örnek uygulamaya aşağıdan ulaşabilirsiniz.

Takipte kalın.

logtracewithcorrelationid