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

Posted on przez Daniel Plawgo

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:

public class HomeController : Controller
{
private static ILogger _logger = NLog.LogManager.GetCurrentClassLogger();
public ActionResult Index()
{
_logger.Info("Home.Index started.");
Random random = new Random();
var value = random.Next(1, 3);
_logger.Info($"Home.Index value is equal {value}");
if (value == 1)
{
_logger.Error("Error during processing value");
throw new Exception("Error during processing value");
}
_logger.Info("Home.Index ended.");
return View();
}
}
view raw HomeController.cs hosted with ❤ by GitHub

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:

class Program
{
static void Main(string[] args)
{
int instances = 5;
var tasks = new Task[instances];
for (int i = 0; i < instances; i++)
{
tasks[i] = Test();
}
Task.WaitAll(tasks);
}
static Task Test()
{
var webClient = new WebClient();
return webClient.DownloadStringTaskAsync("http://localhost:55405/");
}
}
view raw Program.cs hosted with ❤ by GitHub

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:

2019-01-25 06:15:23.7035 INFO Home.Index started.
2019-01-25 06:15:23.7074 INFO Home.Index value is equal 2
2019-01-25 06:15:23.7074 INFO Home.Index ended.
2019-01-25 06:15:23.7035 INFO Home.Index started.
2019-01-25 06:15:23.7035 INFO Home.Index started.
2019-01-25 06:15:23.7074 INFO Home.Index value is equal 2
2019-01-25 06:15:23.7035 INFO Home.Index started.
2019-01-25 06:15:23.7035 INFO Home.Index started.
2019-01-25 06:15:23.7074 INFO Home.Index value is equal 2
2019-01-25 06:15:23.7204 INFO Home.Index ended.
2019-01-25 06:15:23.7074 INFO Home.Index ended.
2019-01-25 06:15:23.7204 INFO Home.Index value is equal 1
2019-01-25 06:15:23.7204 ERROR Error during processing value
2019-01-25 06:15:23.7074 INFO Home.Index value is equal 2
2019-01-25 06:15:23.7384 INFO Home.Index ended.
view raw log1.txt hosted with ❤ by GitHub

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 30 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:

public class MvcApplication : System.Web.HttpApplication
{
protected void Application_Start()
{
AreaRegistration.RegisterAllAreas();
FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
RouteConfig.RegisterRoutes(RouteTable.Routes);
BundleConfig.RegisterBundles(BundleTable.Bundles);
}
protected void Application_BeginRequest(object sender, EventArgs e)
{
Trace.CorrelationManager.ActivityId = Guid.NewGuid();
}
}
view raw MvcApplication.cs hosted with ❤ by GitHub

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):

<?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"
xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
autoReload="true"
throwExceptions="false"
internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
<targets>
<target xsi:type="File" name="f" fileName="${basedir}/App_Data/logs/${shortdate}.log"
layout="${longdate} ${uppercase:${level}} ${activityid} ${message}" />
</targets>
<rules>
<logger name="*" minlevel="Debug" writeTo="f" />
</rules>
</nlog>
view raw NLog.config hosted with ❤ by GitHub

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

2019-01-25 06:15:23.7035 INFO dc6f3750-87a3-41e5-ac56-d9f3453c6581 Home.Index started.
2019-01-25 06:15:23.7074 INFO dc6f3750-87a3-41e5-ac56-d9f3453c6581 Home.Index value is equal 2
2019-01-25 06:15:23.7074 INFO dc6f3750-87a3-41e5-ac56-d9f3453c6581 Home.Index ended.
2019-01-25 06:15:23.7035 INFO 8415583f-c228-4e2e-b5b7-54a568e18f9e Home.Index started.
2019-01-25 06:15:23.7035 INFO 04eaaa85-d320-4e52-9788-0d1aeeab7072 Home.Index started.
2019-01-25 06:15:23.7074 INFO 04eaaa85-d320-4e52-9788-0d1aeeab7072 Home.Index value is equal 2
2019-01-25 06:15:23.7035 INFO 52434052-da54-4b34-a800-8c1dc73ccdf4 Home.Index started.
2019-01-25 06:15:23.7035 INFO 5ffff241-29db-4101-a4df-c3cb4e74dd73 Home.Index started.
2019-01-25 06:15:23.7074 INFO 8415583f-c228-4e2e-b5b7-54a568e18f9e Home.Index value is equal 2
2019-01-25 06:15:23.7204 INFO 8415583f-c228-4e2e-b5b7-54a568e18f9e Home.Index ended.
2019-01-25 06:15:23.7074 INFO 04eaaa85-d320-4e52-9788-0d1aeeab7072 Home.Index ended.
2019-01-25 06:15:23.7204 INFO 5ffff241-29db-4101-a4df-c3cb4e74dd73 Home.Index value is equal 1
2019-01-25 06:15:23.7204 ERROR 5ffff241-29db-4101-a4df-c3cb4e74dd73 Error during processing value
2019-01-25 06:15:23.7074 INFO 52434052-da54-4b34-a800-8c1dc73ccdf4 Home.Index value is equal 2
2019-01-25 06:15:23.7384 INFO 52434052-da54-4b34-a800-8c1dc73ccdf4 Home.Index ended.
view raw log2.txt hosted with ❤ by GitHub

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?

Szkolenie modularny monolit w .NET 5

Szkolenie modularny monolit w .NET 5

Zainteresował Ciebie ten temat? A może chcesz więcej? Jak tak to zapraszam na moje autorskie szkolenie o modularnym monolicie w .NET.

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

Dodaj komentarz

Twój adres e-mail nie zostanie opublikowany.