W poprzednim wpisie przekonywałem dlaczego obserwowalność w aplikacjach webowych jest ważna. Znając już podstawy, czas przejść do szczegółowego omówienia każdego z trzech filarów observability. Na pierwszy ogień na warsztat weźmy najważniejszy z nich, czyli logi.
Structured logging
Logowanie strukturalne – bo tak chyba najlepiej można przetłumaczyć na polski structured logging, to podejście gdzie wszystkie dane logowane są w tym samym formacie, z dodatkowymi informacjami w postaci klucz-wartość. Dzięki temu, takie logi są łatwiejsze do analizy, przeszukiwania i filtrowania (szczególnie w środowiskach rozproszonych). Wpisy opierają się o szablon wiadomości np. „Niepoprawne hasło dla użytkownika {UserLogin}„, który następnie jest uzupełniany dodatkowymi danymi: {„UserLogin„:”j.kowalski@software-forge.pl”, „ClientIp”:”192.168.1.0″}. Dzięki temu możemy łatwo wyszukać wszystkie wpisy o nieudanym logowaniu, ponieważ każdy z nich będzie miał taką samą treść, a różnić się będą jedynie danymi. Taki format jest również wspierany przez wiele narzędzi do analizy i przeglądania logów, np. Grafanę, ElasticSearch lub Seq.
O ile możliwe jest implementowanie logowania strukturalnego samemu, dużo wygodniej jest użyć gotowej biblioteki. W środowisku .NET najpopularniejsze są dwie: Nlog i Serilog i ja skupię się właśnie na tej drugiej. Serilog zapewnia strukturalne logowanie „out of the box”, do tego jest bardzo prosty w konfiguracji i rozszerzaniu o dodatkowe rzeczy. Posiada także szeroką paletę miejsc, do których możemy wysyłać logi, tzw. „sinków„, np. konsola, plik, baza danych itp. Jednym z sinków może zostać collector OpenTelemetry, wtedy logi są od razu spinane z odpowiednimi trace’ami, co ułatwia analizę i nadaje dodatkowy kontekst. Dzięki temu że Serilog „wpina się” w standardowy interfejs ILogger dostarczany przez Microsoft nie jest konieczne żadna modyfikacja kodu aplikacji – wszystkie dotychczasowe logi po prostu działają dalej.
Serilog w praktyce
Konfiguracja i użycie Seriloga jest niezwykle proste. Przykładowo, aby skonfigurować logowanie wszystkich żądań w aplikacji webowej do konsoli:
1. Dodajemy wymagane pakiety
dotnet add package Serilog
dotnet add package Serilog.AspNetCore
dotnet add package Serilog.Sinks.Console2. Tworzymy logger i ustawiamy źródło jego konfiguracji na konfigurację hosta
Umożliwi to automatyczny odczyt ustawień z pliku appsettings.json . Dzięki skorzystaniu z metody CreateBootstrapLogger i ustawieniu konfiguracji na obiekcie hosta, możemy go używać od razu przy uruchamianiu aplikacji, nawet przed zbudowaniem kontenera zależności. Jest to bardzo przydatne do logowania błędów podczas uruchamiania aplikacji.
using var startupLogger = new LoggerConfiguration()
.WriteTo.Console()
.CreateBootstrapLogger();
try
{
var builder = WebApplication.CreateBuilder(args);
builder.Host.UseSerilog((context, configuration) =>
{
configuration.ReadFrom.Configuration(context.Configuration);
});
var app = builder.Build();
app.Run();
}
catch (Exception ex)
{
startupLogger.Fatal(ex, "Unhandled exception");
}3. Dodajemy logowanie requestów
app.UseSerilogRequestLogging();4. Konfigurujemy logger zgodznie z naszymi potrzebami
Przykładowe ustawienia wyświetlające informacje o żądaniach wyglądają następująco:
"Serilog": {
"Using": [
"Serilog.Sinks.Console",
],
"MinimumLevel": {
"Default": "Information"
},
"WriteTo": [
{
"Name": "Console"
}
]
}Używając Seriloga nie powinniśmy korzystać z węzła „Logging„, używanego standardowo do ustawiania poziomów logowania. Zamiast tego te poziomy definiujemy analogicznie w konfiguracji Seriloga, w węźle „MinumumLevel„.
Po zakończeniu konfiguracji i uruchomieniu aplikacji naszym oczom powinny się ukazać się logi z informacjami o requestach.
Dobre praktyki
• Aby uzyskać pełen potencjał logowania strukturalnego należy unikać konkatenowania stringów, a zamiast tego używać parametrów:
// ❌
_logger.LogInformation("User " + userId + " placed order " + orderId);
// ✅
_logger.LogInformation("User {UserId} placed order {OrderId}", userId, orderId);• Używać odpowiedniego poziomu logowania. Dostępne poziomy i krótka ściągawka kiedy stosować każdy z nich:
- Trace – najbardziej szczegółowy i najrzadziej używany poziom. Przydatny do debugowania i śledzenia skomplikowanych scenariuszy.
- Debug – szczegółowe informacje, przydatne dla developerów przy troubleshootingu.
- Information – ogólne informacje i zdarzania w systemie, pomagające śledzić ścieżkę wykonania, kluczowe akcje oraz stan.
- Warning – niespodziewane zdarzenia, które nie przerywają wykonania. Przydatny do namierzania potencjalnych problemów.
- Error – błędy przerywające wykonanie aktualnej operacji, ale nie zaburzające działania całej aplikacji.
- Fatal – najwyższy poziom, krytyczne błędy wpływające na cały system, lub przerywające działanie całej aplikacji.
Poziomy logowania można ustawiać globalne, lub per konkretny logger (namespace). Warto zauważyć również że bardziej szczegółowy poziom logowania może mieć negatywny wpływ na wydajność aplikacji, ponieważ odkładanych zdarzeń robi się coraz więcej.
• Dodać automatyczne rozszerzanie logów o kontekst przy pomocy tzw. „enricherów„
Enrichery to rozszerzenia Seriloga, automatycznie dodające informacje do strukturalnych logów. Skonfigurowane wcześniej logowanie requestów można rozszerzyć np. o correlation id (unikalny identyfikator requestu) przy użyciu pakietu Serilog.Enrichers.ClientInfo.
Żeby to zrobić rozszerzamy konfigurację loggera:
builder.Host.UseSerilog((context, configuration) =>
{
configuration.ReadFrom.Configuration(context.Configuration);
configuration.Enrich.WithCorrelationId();
});lub rozszerzamy konfigurację w pliku appsetting.json:
"Serilog": {
"Using": [
"Serilog.Sinks.Console",
"Serilog.Enrichers.ClientInfo"
],
"MinimumLevel": {
"Default": "Information"
},
"Enrich": [
"WithCorrelationId"
],
"WriteTo": [
{
"Name": "Console"
}
]
}Możliwe jest dopisywanie własnych enricherów i dostosowywanie kontekstowych informacji do własnych potrzeb. Istnieje też wiele innych predefiniowanych enricherów w formie pakietów, tak jak użyte w przykładzie ClientInfo.
• Pamiętać o maskowaniu danych wrażliwych.
To tyczy się każdych logów, nie tylko strukturalnych. Logowanie haseł użytkowników to nie najlepszy pomysł 😉
Logi najlepszym przyjacielem programisty
Logowanie strukturalne to świetny sposób na polepszenie jakości obserwowalności aplikacji. Dzięki nim dostajemy coś więcej niż tylko informację o tym że jakieś zdarzenie zaszło – możemy dodać do niego kontekst oraz istotne informacje np. stan systemu. Jest to nieocenione ułatwienie przy diagnozie problemów, szczególnie w systemach rozproszonych, który naturalnie rozbudowuje zamiast standardowy sposób tekstowego logowania, nie łamiąc przy tym kompatybilności. Ponadto jest to ogólnie przyjęty standard, coraz bardziej zyskujący na popularności i wspierany przez wiele narzędzi.
Jak widać na przykładzie Seriloga, dodanie takiego logowania przy użyciu zewnętrznych bibliotek jest bardzo proste i nie wymaga większych zmian w aplikacji. Bogatość opcji konfiguracyjnych i dostępnych sinków gwarantuje też możliwość dostosowania logów do swoich potrzeb. Jedynymi minusem takiego rozwiązania, jest brak bezpośredniego dostępu do kodu i konieczność dodawania wielu paczek. Wydaje mi się jednak że zysk z używania sprawdzonego w boju rozwiązania z żyjącą społecznością, oraz oszczędność czasu w stosunku do pisania własnego jest tego warty.
Konfiguracja Seriloga to teraz pierwszy punkt na mojej liście przy startowaniu nowego projektu. A ty? Dalej chcesz używać Console.WriteLine? 😉