Enterprise Library Logging Application Block - część II 

Autor: Piotr Zieliński

Opublikowano: 2013-08-21

Wprowadzenie

Cześć I artykułu dotyczyła podstaw EntLib Logging Application Block. Druga cześć z kolei omawia bardziej zaawansowane mechanizmy, przydatne w większych aplikacjach. Logi mogą być zapisywane w różnym miejscach, również w relacyjnej bazie danych. Czasami czas wymagany na wykonanie takiego logu jest zauważalny stąd asynchroniczny sposób na zapis może okazać się wysoce przydatny. Współczesne aplikacje generują tyle zdarzeń, że ciężko potem analizować taki log. Pomóc mogą w tym filtry, aby zapisywać tylko te dane, które rzeczywiście przydatne są w danym kontekście. Ponadto, aby powiązać ze sobą poszczególne logi w całość, klasa TraceManager pomoże wygenerować identyfikator korelacyjny. Nie zawsze szczegółowe informacje są potrzebne stąd dynamiczna zmiana konfiguracji jest bardzo przydatna i powinna być praktykowana przez osoby zajmujące się wsparciem danej aplikacji.

Filtrowanie

Istnieje wiele sposobów filtrowania logów. W poprzedniej części artykułu, pokazano jak zapisywać logi w konkretnej lokalizacji w zależności od kategorii lub SourceLevel (srogość)

W poprzedniej części również wspomniano o klasie LoggingConfiguration oraz konfiguracji logger’a. W tej części przyszedł czas pokazać jak nakładać filtry, tak, aby niektóre wiadomości były po prostu ignorowane.

Klasa LoggingConfiguration posiada właściwość Filters, która stanowi po prostu listę filtrów. Pierwszym, najprostszym filtrem jest LogEnabledFilter:

internal class Program
{
    private static void Main()
    {
        var logWriter = new LogWriter(BuildConfiguration());

         if (logWriter.IsLoggingEnabled())
        {
            logWriter.Write("Test","Important");
        }

        }
        private static LoggingConfiguration BuildConfiguration()
        {
            var loggingConfiguration = new LoggingConfiguration();

            var flatFileListener = new FlatFileTraceListener(@"c:\temp\1.txt");

            loggingConfiguration.AddLogSource("Important", SourceLevels.All, true).
            AddTraceListener(flatFileListener);

            loggingConfiguration.Filters.Add(new LogEnabledFilter("nazwa filtru",false));
            return loggingConfiguration;
    }
}

Konstruktor LogEnabledFilter przyjmuje dwie wartości: nazwę filtru oraz flagę określającą czy należy zablokować logi. Przekazanie false, zablokuje zapis jakichkolwiek logów a logWriter.IsLoggingEnabled() będzie zwracał zawsze false.

Innym typem filtru jest CategoryFilter, który umożliwia zdefiniowanie, jakie logi powinni być przetwarzane. Konstruktor CategoryFilter przyjmuje kolejno: nazwę filtru, listę kategorii oraz typ filtra tzn. CategoryFilterMode.AllowAllExceptDenied lub CategoryFilterMode.DenyAllExceptAllowed.

Przekazanie AllowAllExpectDenied spowoduje, że logi z kategoriami przekazanymi do konstruktora filtra będą ignorowane. Z kolei DenyAllExpectAllowed ma przeciwne znaczenie – wyłącznie kategorie przekazane do konstruktora będą akceptowane. Przykład:

var categoryFilter=new CategoryFilter("nazwa 1",new[]{"Important"},CategoryFilterMode.DenyAllExceptAllowed);
loggingConfiguration.Filters.Add(categoryFilter);

Bardzo przydatnym filtrem jest PriorityFilter:
loggingConfiguration.Filters.Add(new PriorityFilter("nazwa",minimumPriority:5,maximumPriority:10));

Klasa, jak łatwo można domyślić się, dopuści wyłącznie logi, pomiędzy priorytetem zdefiniowanym przez parametr minimumPriority a maximumPriority. Możliwe jest również użycie innego przeładowania, akceptującego tylko parametr minimumPriority.

Ponadto, można implementować własne filtry, dziedzicząc po klasie LogFilter:

class CustomFilter:LogFilter
{
    public CustomFilter(string name) : base(name)
    {
    }
    public override bool Filter(LogEntry log)
    {
        // wlasna logika
        throw new NotImplementedException();
    }
}

Metoda Filter zwraca true, jeśli log powinien zostać zapisany lub false w przeciwnym wypadku.

Oczywiście możliwe jest zdefiniowane filtrów w pliku konfiguracyjnym, co jest dużo częstszym przypadkiem zastosowania w praktyce. Wystarczy użyć, opisanego w poprzedniej części artykułu narzędzia Enterprise Library Configuration:

Specjalne źródła logów

W poprzednich przykładach konfigurowano różne „trace source” oraz „trace listeners”. Umożliwia to przekierowywanie logów do danej lokalizacji w zależności od kategorii czy priorytetu. EntLib dostarcza dodatkowo kilka specjalnych źródeł logów, które zawsze istnieją, niezależnie od własnej konfiguracji.

Pierwszym źródłem jest „All Events”, który domyślnie nie ma podczepionych żadnych listener’ów. Wpadają do niego wszystkie logi, niezależnie czy zostały już przechwycone przez jakieś skonfigurowane źródło czy nie. Perfekcyjnie nadaje się do implementacji dziennika audytowego.

Drugim specjalnym źródłem jest „Unprocessed” – zawiera wszystkie logi, które nie zostały dopasowane do żadnego „trace source”. Podobnie jak „All Events”, domyślnie nie ma żadnych listener’ów podpiętych pod „Unprocessed”.

Jeśli podczas zapisu został wyrzucony wyjątek to trafi on do źródła o nazwie „LoggingErrorsAndWarnings”. Domyślnie wszystkie logi z tego źródła lądują w Windows Events Log. Kiedy może wystąpić wyjątek podczas zapisywania logu? Jeśli lokalizacją wpisów jest baza danych, może okazać się, że connection string jest źle skonfigurowany lub po prostu baza danych nie istnieje.

Wszystkie specjalne źródła można konfigurować za pomocą właściwości Special Sources:

loggingConfiguration.SpecialSources.AllEvents.AddTraceListener(flatFileListener1);
loggingConfiguration.SpecialSources.Unprocessed.AddTraceListener(flatFileListener2);
loggingConfiguration.SpecialSources.LoggingErrorsAndWarnings.AddAsynchronousTraceListener(flatFileListener3);

Zapisywanie logów w relacyjnej bazie danych

Jak już zostało to wspomniane, logi można zapisywać w bazie danych np. w SQL Server. Najpierw należy jednak zainstalować z NuGet Enterprise Library – Logging Application Database Provider:

Kolejnym krokiem jest wygenerowanie odpowiednich tabel w bazie danych. W tym celu należy uruchomić skrypt CreateLoggingDatabaseObjects znajdujący się w folderze Enterprise Library. Po jego uruchomieniu następująca struktura powinna zostać wygenerowana w bazie danych:

Ponadto skrypt wygeneruje kilka procedur, a mianowicie: AddCategory, ClearLogs, InsertCategoryLog, WriteLog.

Baza danych jest już skonfigurowana, można, więc przejść do konfiguracji po stronie klienta:

var database=new SqlDatabase(@"Connection String");
var databaseTraceListener= new FormattedDatabaseTraceListener(database,"WriteLog", "AddCategory",new TextFormatter());

Najpierw należy stworzyć obiekt Database, w naszym przypadku jest to SqlDatabase. Konstruktor tej klasy przyjmuje, jako parametr connection string. Następnie można stworzyć listener, którym jest FormattedDatabaseTraceListener, przekazując właśnie stworzony obiekt Database, nazwy procedur (utworzonych w poprzednich krokach) oraz obiekt odpowiedzialny za formatowanie (w naszym przypadku po prostu TextFormatter). Warto wspomnieć, że zamiast TextFormatter, można przekazać BinaryLogFormatter, JsonLogFormatter, XmlLogFormatter.

Następnie zapis logów wygląda dokładnie tak samo np.:

var logWriter = new LogWriter(BuildConfiguration());

if (logWriter.IsLoggingEnabled())
{
    logWriter.Write("Test","Important");
}

Po zapisie, baza danych będzie wyglądać następująco:

W kolumnie FormattedMessage znajduje się wpis, sformatowany w zależności od przekazanego obiektu.

Wykonywanie logów w sposób asynchroniczny

Czasami zapis logu można potrwać dość długo, zwłaszcza, jeśli do czynienia ma się np. z bazą danych. Logowanie powinno odbywać się w sposób jak najbardziej transparentny, ponieważ nie jest to funkcjonalność systemu a jedynie jego instrumentacja. Końcowy użytkownik w większości przypadków nie zainteresuje się logami, dlatego czasami wskazane jest korzystanie z asynchronicznego zapisu. W EntLib jest to bardzo proste, wystarczy wywołać AddAsynchronousTraceListener zamiast AddTraceListener:

LoggingConfiguration loggingConfiguration=new LoggingConfiguration();

 loggingConfiguration.SpecialSources.AllEvents.AddAsynchronousTraceListener(databaseTraceListener);

Dynamiczna zmiana konfiguracji

W momencie, gdy są wątpliwości dotyczące działania aplikacji, naturalne jest, że należy zajrzeć do logów. Czasami jednak zawarte w nich informacje są niewystarczające. Ze wspomnianych wydajnościowych przyczyn nie warto zawsze zapisywać wszystkie dostępne informację. W momencie jednak podejrzanego zachowania aplikacji nie ma wyboru. Można oczywiście zamknąć aplikację, zmienić plik konfiguracyjny i ponownie ją uruchomić. W praktyce jednak, rzadko jest to możliwe. Jeśli system jest wykorzystywany aktualnie przez użytkowników wyłączenie jego jest nie do zaakceptowania. Oczywiście, jeśli wątpliwości są dość duże to wtedy lepiej przerwać działanie aplikacji. Czasami jednak administrator chciałby przyjrzeć się bliżej działaniu aplikacji, przy czym poziom ryzyka nie jest aż tak wysoki. EntLib umożliwia dynamiczną zmianę konfiguracji za pomocą metody LogWriter::Configure:

private static void ChangeConfiguration(LogWriter logWriter)
{
    logWriter.Configure(cfg =>
    {
         cfg.Filters.Clear();                                

         var priorityFilter = new PriorityFilter("Priority Filter", 2, 5);
         var logEnabledFilter = new LogEnabledFilter("LogEnabled Filter", true);

         ICollection<string> categories = new List<string>();
         categories.Add("Important");
         categories.Add("General");                

         var categoryFilter = new CategoryFilter("Category Filter", categories, CategoryFilterMode.AllowAllExceptDenied);

         cfg.Filters.Add(priorityFilter);
         cfg.Filters.Add(logEnabledFilter);
         cfg.Filters.Add(categoryFilter);

         cfg.SpecialSources.AllEvents.AddTraceListener(...);
         cfg.SpecialSources.LoggingErrorsAndWarnings.AddTraceListener(...);
         cfg.SpecialSources.Unprocessed.AddTraceListener(...);
    });
}

Można zdefiniować sobie kilka metod w projekcie do szczegółowej i podstawowej konfiguracji. W razie potrzeby, w łatwy sposób można wtedy zmienić tymczasowo konfigurację.

Śledzenie logów

Utrzymanie aplikacji może być bardzo trudnym zadaniem, szczególnie, gdy nie można znaleźć przyczyn błędu, który zdarzył się na produkcji. Logi oczywiście mają w tym pomóc. Czasami jednak, jest tam tak dużo informacji, że ciężko powiedzieć, który log dotyczy, jakiej operacji. Szczególnie, gdy do czynienia ma się z wielowątkowym systemem, gdzie wątki przeplatają się wzajemnie. W EntLib istnieje sposób tagowania wpisów identyfikatorem zależnym od aktualnie wykonywanego kodu. Następnie przeglądając logi można za pomocą jego wyznaczyć korelacje między rożnymi wpisami.

Wystarczy użyć klasy TraceManager:

var logWriter = new LogWriter(BuildConfiguration());
var traceManager = new TraceManager(logWriter);

using (traceManager.StartTrace("General"))
    {
        logWriter.Write("Test 2");
    }

W konstruktorze należy przekazać oczywiście LogWriter. Następnie, w celu rozpoczęcia jakieś operacji wywoływana jest metoda StackTrace. Jeśli się nie przekaże samodzielne identyfikatora, wtedy zostanie wygenerowany  automatycznie GUID operacji. Wymagany parametr to nazwa kategorii, z jaką wszystkie następne logi będą wykonywane. Początek będzie wyglądał następująco:

All Events Start: 1 : Timestamp: 25/07/2013 20:36:30
Message: Start Trace: Activity 'f0037167-7994-4527-83af-6a43356ef44c' in method 'ConsoleApplication1.Program.Main' at 229055191949 ticks
Category: General

Widać unikalny identyfikator, a mianowicie 'f0037167-7994-4527-83af-6a43356ef44c'. Wszystkie operacje wykonane w obrębie powyższego using będą posiadać taki sam korelacyjny id.

Możliwe jest również zagnieżdżanie korelacji:

private static void Main(string[] args)
{
    var logWriter = new LogWriter(BuildConfiguration());
    var traceManager = new TraceManager(logWriter);

    using (traceManager.StartTrace("General"))
    {
        logWriter.Write("Test 1");
        using (traceManager.StartTrace("Important"))
        {
            logWriter.Write("Test 2");
        }
    }
}

Domyślnie zagnieżdżone elementy dziedziczą id po rodzicu. W tym przypadku wiadomości Test 1  i Test 2 będą miały taki sam id czyli z punktu interpretacyjnego, dotyczą one tej samej części logiki. Wiadomość „Test2” będzie skojarzona z dwoma kategoriami („Important”, „General”).

Oczywiście każdy log może przekazać swoje kategorie, które będą dopełnieniem tej przekazanej w using:

private static void Main(string[] args)
{
    var logWriter = new LogWriter(BuildConfiguration());
  
    var traceManager = new TraceManager(logWriter);

    using (traceManager.StartTrace("General"))
    {
        logWriter.Write("Test 1","Warnings");
        using (traceManager.StartTrace("Important"))
        {
            logWriter.Write("Test 2", "Warnings");
        }
    }
}

Gdy przekaże się jawnie identyfikator, wtedy nie będzie on dziedziczony od rodzica:

private static void Main(string[] args)
{
    var logWriter = new LogWriter(BuildConfiguration());
   
    var traceManager = new TraceManager(logWriter);

    using (traceManager.StartTrace("General"))
    {
        logWriter.Write("Test 1","Warnings");
        using (traceManager.StartTrace("Important",Guid.NewGuid()))
        {
            logWriter.Write("Test 2", "Warnings");
        }
    }
}

Powyższe przykłady mają zastosowanie wyłącznie w dużych systemach (szczególnie wielowątkowych), gdzie dzienniki zawierają tak dużo informacji, że ciężko poszczególne wpisy skojarzyć z konkretnie wykonywaną czynnością. Dla prostych systemów, których logika wykonywana jest w dużym stopniu szeregowo (sekwencyjnie), nie ma sensu stosować TraceManager.

Własne implementacje listener’a oraz formatera

EntLib jest wysoko skalowalny, więc w zasadzie każdą operacje można wykonać po swojemu, jeśli zachodzi taka potrzeba. Na przykład można zaimplementować własny TraceListener, wystarczy dziedziczyć po CustomTraceListener i zaimplementować  dwie metody:

class CustomListener : CustomTraceListener
{
    public override void Write(string message)
    {
        throw new NotImplementedException();
    }

     public override void WriteLine(string message)
    {
        throw new NotImplementedException();
    }
}

Jeśli, któryś z dostarczonych formaterów nie spełnia wymagań można zaimplementować ILogFormatter:

class CustomFormatter : ILogFormatter
{
    public string Format(LogEntry log)
    {
        throw new NotImplementedException();
    }
}

Moim zdaniem, powyższe przykłady pokazują, że naprawdę łatwo dostosować EntLib do własnych potrzeb. W większości przypadków jednak w zupełności wystarczą implementacje dostarczone przez EntLib.

Zakończenie

Myślę, że EntLib Log Block, ma wszystko, co należałoby spodziewać się po tego typu bibliotekach. Szczególnie ciekawym rozwiązaniem jest TrackManager, który ułatwia identyfikacje błędów, kodu będącego już na produkcji. Artykuł jednak z pewnością nie wyczerpuje tematu i w kolejnej części będzie o Semantic Logging Application Block.

 

---

          

Piotr Zieliński

Absolwent informatyki o specjalizacji inżynieria oprogramowania Uniwersytetu Zielonogórskiego. Posiada szereg certyfikatów z technologii Microsoft (MCP, MCTS, MCPD). W 2011 roku wyróżniony nagrodą MVP w kategorii Visual C#. Aktualnie pracuje w General Electric pisząc oprogramowanie wykorzystywane w monitorowaniu transformatorów . Platformę .NET zna od wersji 1.1 – wcześniej wykorzystywał głównie MFC oraz C++ Builder. Interesuje się wieloma technologiami m.in. ASP.NET MVC, WPF, PRISM, WCF, WCF Data Services, WWF, Azure, Silverlight, WCF RIA Services, XNA, Entity Framework, nHibernate. Oprócz czystych technologii zajmuje się również wzorcami projektowymi, bezpieczeństwem aplikacji webowych i testowaniem oprogramowania od strony programisty. W wolnych chwilach prowadzi blog o .NET i tzw. patterns & practices.