Semantic logging w ASP.NET Core: Serilog + Elasticsearch

Czas czytania ~ 180 sekund

Zdarzenia w aplikacji logować oczywiście trzeba. Często informacje budujemy w ten sposób, by były czytelne dla kolejnej osoby, która otworzy taki plik z logiem. Przykład:

User jkowalski failed to log in at 2016-12-30 09:21:04 from 192.0.78.25

Niby mamy wszystkie informacje, jest to czytelne dla człowieka. Problem pojawia się, gdy takich logów będziemy mieli naprawdę sporo i nastąpi potrzeba odfiltrowania takiego pliku, na przykład tylko do zdarzeń niepoprawnego zalogowania, albo tylko do zdarzeń niepoprawnego zalogowania z tego adresu IP.

Jeśli wrzucamy to do pliku tekstowego, możemy bawić się w Regexy, w bazie możemy próbować zapytań z operatorem LIKE. Na dłuższą metę jednak jest to skrajnie niewygodne, może być błędogenne i jeśli takich wpisów będzie dużo, to możemy również mieć problemy z wydajnością podczas przeszukiwania.

Domyślne logowanie w ASP.NET Core

Po założeniu nowej aplikacji w VS od razu mamy skonfigurowane logowanie zdarzeń na konsolę. Domyślnie leci to wszystko na konsolę Visuala, jeśli przełączymy się  z IISExpress na Kestrela, to przy uruchomieniu wyskoczy nam również konsolowe okienko w którym możemy czytać logi aplikacji. Cała koncepcja oparta jest o poziomy logowania, jeśli włączymy sobie Debug, jak poniżej, to aplikacja będzie wyrzucała informacje od poziomu Information w górę.

logger

Po wdrożeniu tego na IIS możemy dodać przekierowanie stdout do plików atrybutami stdoutLogEnabled i stdoutLogFile.

<system.webServer>
	<aspNetCore processPath="dotnet" arguments=".\MyWebApp.dll" stdoutLogEnabled="true" stdoutLogFile=".\..\logs\stdout" forwardWindowsAuthToken="false" />
</system.webServer>

I w wielu prostych przypadkach to może wystarczyć. Mamy dostępnych kilka providerów (konsola, EventLog Windows, Azure App Service, EventSource, TraceSource). Jeśli jednak chcemy, by nasze logi lądowały gdzie indziej musimy skorzystać z innych providerów, takich jak NLog czy log4net.

Serilog

Alternatywą dla wymienionych bibliotek jest Serilog, który oferuje wygodną funkcjonalność logowania w sposób ustrukturyzowany. Chodzi zatem o to, by zapisywać zdarzenia w logu tak, by były przede wszystkim czytelne dla maszyny. W związku z tym niespecjalnie atrakcyjne będzie zapisywanie takich danych w pliku tekstowym, natomiast ekstremalnie ciekawe wydaje się wrzucanie takich danych do baz NoSql ze względu na to, że tamtejsze kolekcje często dopuszczają dynamiczny schemat danych (różne zdarzenia mogą być zapisane w jednej tabeli / kolekcji / indeksie i przeszukiwane jednym zapytaniem).

Ujść danych dla Seriloga (sinks) w momencie pisania tego posta jest 56 (przełom 2016 i 2017) i możemy je doinstalowywać jako kolejne NuGety. Cała lista dostępna jest tutaj. Mamy więc do dyspozycji m.in. MongoDB, Elasticsearch, RavenDB, Slack czy SignalR.

Integracja z ASP.NET Core

Rozpoczynamy od doinstalowania kilku NuGetów.

serilog

Do integracji z ASP.NET przyda się  Serilog.Extensions.Logging, jeśli chcemy zapisywać do plików to potrzebny będzie jeszcze  Serilog.Extensions.Logging.File. I kilka linii kodu. Konfigurację może załadować z AppSettingsów (potrzebny dodatkowy pakiet NuGeta) lub użyć FluentAPI, uzależniając go np. od interfejsu IHostingEnvironment z ASP.NET Core

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{          
    loggerFactory.AddSerilog();
    ConfigureSerilog(env);
    //...
}

private void ConfigureSerilog(IHostingEnvironment env)
{
    var configuration = new LoggerConfiguration();

    if (env.IsProduction())
    {
        configuration = configuration.MinimumLevel.Warning();
    }
    else
    {
        configuration = configuration.MinimumLevel.Information();
    }

    Log.Logger = configuration
                    .Enrich.FromLogContext()
                    .WriteTo.File("../logs.txt")
                    .CreateLogger();
}

Mamy już zintegrowany ASP.NET Core z Serilogiem, wiadomości możemy wypisywać wstrzykując przez DI do kontrolerów interfejs ILogger<T>.

public class HomeController : Controller
{
    private ILogger<HomeController> _logger;

    public HomeController(ILogger<HomeController> logger)
    {
        _logger = logger;
    }

    public IActionResult Index()
    {
        _logger.LogInformation("Entering Index at Home Controller");
        return View();
    }
}

W naszym pliku wyjściowym znajdzie się zarówno to, co wypisuje za nas ASP.NET jak i nasze wpisy.

Semantic logging i destructuring operator

Prawdziwy power Seriloga można odczuć, gdy chcemy zalogować całe obiekty. Przykładowo dla prostej klasy DTO z dwoma polami możemy przekazać obiekt jako zwykły parametr loggera lub zrobić to przy użyciu operatora destrukturyzacji.

public IActionResult MyMethod(MyMethodDto dto)
{
    _logger.LogDebug("Reached MyMethod with following params:{dto}", dto);
    _logger.LogDebug("Reached MyMethod with following params:{@dto}", dto);

    return View();
}

W logach wygląda to tak:

2016-12-28 13:30:19.481 +01:00 [Warning] Reached MyMethod with following params:”12, john”
2016-12-28 13:30:19.486 +01:00 [Warning] Reached MyMethod with following params:MyMethodDto { Id: 12, Name: “john” }

W pierwszym przypadku wywoła się przeładowana wcześniej przeze mnie metoda ToString. Jest to skrajnie niewygodne, na szczęście dzięki wspomnianemu operatorowi Serilog sam potrafi serializować obiekty. Możemy globalnie skonfigurować, które properties mają się logować, jeśli nie chcemy, by wszystko lądowało w logu.

Elasticsearch do przeszukiwania

Skoro potrafimy wygodnie logować całe obiekty to możemy wykorzystać Elasticsearch do tego, by w prosty sposób przeszukiwać ogromne ilości danych z takich logów. Instalujemy jeden dodatkowy NuGet Serilog.Sinks.Elasticsearch, w konfiguracji dodajemy linijkę WriteTo.Elasticsearch()

Jeśli nie podamy żadnych parametrów to Serilog poszuka Elasticsearcha pod domyślnym portem 9200 na localhoscie i założy odpowiedni indeks. Tak wygląda struktura pojedynczego zalogowanego dokumentu.

es

Możemy więc przeszukiwać zarówno po strukturze zalogowanego DTO (obiekt fields) jak i po messageTemplate, tak, by odfiltrować wyniki do określonego miejsca w kodzie logującym.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s