Grupowanie wiadomości w NLogu w ramach żądania HTTP

Wprowadzenie

Logowanie działania aplikacji jest bardzo przydatne podczas późniejszej analizy tego, co się stało. Na ogół prawie każda aplikacja loguje jakieś informacje. Niestety zauważyłem, że równie często nie do końca dobrze logujemy wiadomości. Jest to szczególnie widoczne w aplikacjach webowych (na przykład w ASP.NET MVC). Przy dużej liczbie użytkowników wiadomości z poszczególnych żądań są wymieszane między sobą, przez co ich późniejsza analiza jest bardzo utrudniona – i zamiast skorzystać z ich pomocy, często poświęcamy godziny na ich analizę. W tym wpisie będę chciał Ci pokazać, jak rozwiązać ów problem w przypadku mojej ulubionej biblioteki do logów, czyli NLoga.

Zwykłe logowanie

Wpis zaczniemy od analizy problematycznej sytuacji. Utworzyłem bardzo prostą aplikację, do której dodałem NLoga oraz zmodyfikowałem akcję Index kontrolera Home, aby w logu zapisywała kilka wiadomości:

Nie ma tutaj nic skomplikowanego. Na początku akcji zapisujemy informacje o jej starcie. Później losujemy liczbę i jej wartość również zapisujemy w logu. Na końcu na podstawie wylosowanej liczby decydujemy, czy akcja ma wyrzucić wyjątek, czy wyświetlić widok. Odpowiednio też logujemy informacje o decyzji.

Przygotowałem również prostą aplikację konsolową, która wyśle w tym samym czasie 5 żądań do testowej akcji, aby zasymulować korzystanie z aplikacji przez wielu użytkowników. Dzięki temu uzyskamy wymieszane wiadomości w logu, jak zobaczymy za chwilkę.

Kod aplikacji konsolowej wygląda tak:

Aplikacja tworzy 5 tasków, które równolegle wysyłają żądanie do testowej akcji, aby zasymulować równoległe korzystanie z aplikacji.

Wynikowy log wygląda tak:

O ile jeszcze w przypadku pierwszego żądania jesteśmy w stanie powiązać ze sobą poszczególne linie, to już w przypadku kolejnych niestety nie możemy tego zrobić.

Zobaczmy, w jaki sposób możemy rozwiązać ten problem z wykorzystaniem ActivityId.

Darmowy kurs Visual Studio

Pracując z setkami programistów, zauważyłem, że większość osób nie pracuje efektywnie w Visual Studio. W skrajnych przypadkach korzystali z kopiowania z wykorzystaniem menu Edit. Wiem, że to dziwne, ale naprawdę niektórzy tak pracują. Dlatego postanowiłem stworzyć kurs Visual Studio – aby pomóc koleżankom i kolegom w efektywniejszej pracy.

Przygotowałem 20 lekcji e-mail, w których pokażę Ci, w jaki sposób pracować efektywniej i szybciej w Visual Studio. Poznasz dodatki, bez których nie wyobrażam sobie pracy w tym IDE.

Po więcej informacji zapraszam na dedykowaną stronę kursu: Darmowy Kurs Visual Studio.

Quiz C#

Ostatnio przygotowałem również quiz C#, w którym możesz sprawdzić swoją wiedzę. Podejmiesz wyzwanie?

Dodanie ActivityId

Klasa Trace udostępnia właściwość CorrelationManager, która następnie udostępnia ActivityId. Dzięki tej właściwości możemy w sposób logiczny grupować operacje wykonywane w aplikacji. Właściwość jest powiązana z aktualnie wykonywanym wątkiem. W przypadku aplikacji ASP.NET MVC możemy na początku żądania wygenerować nowego Guida i przypisać go do ActivityId:

Dzięki temu możemy później tę wartość dodawać do wiadomości podczas zapisu logów.

W przypadku NLoga jest o tyle jeszcze łatwiej, że w formacie wiadomości zapisywanej do logu możemy skorzystać z ${activityid} i automatycznie zapisywać wartość z ActivityId w logu bez konieczności przekazywania tej wartości do metody wykonywanej na logerze (kod akcji Index nie został zmieniony):

Po użyciu ActivityId w logach możemy już bez problemu powiązać poszczególne wiadomości z jednego żądania:

Analiza loga

Mając już taki log z ustawionym ActivityId, możemy go przefiltrować i zacząć analizę wykonywania akcji kontrolera. W tym celu na ogół wykorzystuję narzędzie o nazwie grepWin (https://tools.stefankueng.com/grepWin.html). To taka okienkowa wersja komendy grep z linuxa.

Po zainstalowaniu oraz uruchomieniu aplikacji wskazujemy folder, w którym znajdują się logi (punkt 1 na poniższym rysunku). Ustalamy, że interesuje nas wyszukiwanie tekstu (możemy też skorzystać z wyrażenia regularnego – punkt 2). Wpisujemy wartość interesującego nas ActivityId (punkt 3). Przeszukujemy pliki z logami za pomocą przycisku Search (punkt 4). Niżej domyślnie zobaczymy listę plików z daną wartością. Gdy przełączymy się do widoku zawartości (radio button Content punkt 5), zobaczymy listę wszystkich linii dla danego ActivityId:

nlog activityid grepwin

Prawda, że dużo łatwiej tak przeanalizować, co się działo w ramach danego żądania i dlaczego wystąpił błąd?

Przykład

Na githubie znajduje się przykład (https://github.com/danielplawgo/LoggingRequest), który wykorzystywałem podczas pracy nad tym wpisem. Po pobraniu go nie jest wymagana żadna dodatkowa konfiguracja. Wystarczy najpierw uruchomić aplikację ASP.NET MVC i później aplikację konsolową. W katalogu App_Data\logs pojawią się logi z działania aplikacji.

Podsumowanie

Logi są istotnym elementem w utrzymywaniu działania aplikacji. Dzięki nim możemy dowiedzieć się wielu ciekawych rzeczy na temat naszych systemów. Musimy też pamiętać o tym, żeby ułatwiać sobie późniejszą ich analizę. Pokazany w tym wpisie ActivityId bardzo to usprawnia. Bo co z tego, że będziemy mieli gigabajty logów, jeśli nie będziemy w stanie z nich niczego sensownego wyciągnąć?

A jak Ty sobie radzisz w takiej sytuacji?

1 thought on “Grupowanie wiadomości w NLogu w ramach żądania HTTP

Dodaj komentarz

Twój adres email nie zostanie opublikowany. Pola, których wypełnienie jest wymagane, są oznaczone symbolem *