Backend Notları 6: Serilog ile Yapılandırılmış Loglama

Önceki notta, canlı sistemlerin bana sabahın üçünde soracağınız soruya cevap veren loglamanın değerini öğrettiğini söylemiştim. Bu not, böyle bir loglamanın bir ASP.NET Core servisinde nasıl göründüğünü ve bir logun kanıt mı yoksa gürültü mü olacağını belirleyen küçük kararları anlatıyor.

Serilog'u Gozine2'de 2021'de, henüz orada full-stack çalışırken devreye aldım; kıdemli backend rolüne geçtikten sonra da yapılandırılmış loglama, Docker ve CI/CD'nin yanında standart kurulumun bir parçası olarak kaldı. Amaç hiçbir zaman daha güzel bir konsol değildi. Amaç, "bir öğrenci sınavın donduğunu söylüyor" noktasından başarısız olan isteğe, o isteğin ait olduğu kullanıcıya ve sınava, her adımın ne kadar sürdüğüne ve isteği hangi exception'ın sonlandırdığına giden yolu kısaltmaktı. Paket kurmak işin küçük kısmıydı; asıl iş, her olayın neyi taşıması gerektiği konusunda anlaşmaktı.

String'ler değil, mesaj şablonları

En önemli alışkanlık aynı zamanda en küçüğüdür. Şu iki çağrıyı karşılaştırın:

// Interpolated: the values are baked into the text, so every call is a different message
logger.LogWarning($"Answer save took {elapsed.TotalMilliseconds} ms for session {sessionId}");

// Template: one event type with two properties you can query
logger.LogWarning("Answer save took {ElapsedMs} ms for session {SessionId}",
    elapsed.TotalMilliseconds, sessionId);

İlk satır bir string üretir. İkincisi ise sabit bir şablonu ve iki isimli property'si olan bir olay üretir; böylece bir log deposu, düzenli ifadelere gerek kalmadan "500 ms'nin üzerindeki tüm yavaş kaydetme işlemlerini göster" ya da "uyarıları şablona göre grupla" sorularını yanıtlayabilir. Interpolation kullanan sürüm ayrıca string'ini, logger Warning seviyesinin açık olup olmadığını kontrol etmeden önce oluşturur. .NET analyzer'ları bunu CA2254, "Template should be a static expression" olarak işaretler; ben de code review'da bu uyarıyı hata olarak ele alıyorum.

İki ayrıntıda hata yapmak kolaydır. LogWarning gibi ILogger extension method'larında yer tutucular argümanlarla isimle değil, sırayla eşleştirilir; yani {SessionId} ikinci sırada ne geliyorsa onu alır. {@Request} örneğindeki @ operatörü ise Serilog'a nesnenin tamamını serialize etmesini söyler. Bu hem kullanışlı hem tehlikelidir: seneye eklenecekler dâhil her public property'yi loglarsınız. Ben gereken birkaç property'yi tek tek adlandırmayı tercih ederim.

Hot path'ler için [LoggerMessage] source generator'ı aynı yapılandırılmış olayı, her çağrıda boxing yapmadan ve şablonu yeniden ayrıştırmadan üretir; Serilog aynı ILogger soyutlamasının arkasında durduğu için Serilog ile de çalışır:

public static partial class ExamLog
{
    [LoggerMessage(EventId = 1001, Level = LogLevel.Warning,
        Message = "Answer save took {ElapsedMs} ms for session {SessionId}")]
    public static partial void SlowAnswerSave(ILogger logger, double elapsedMs, Guid sessionId);
}

Exception'ların kendi yeri vardır ve bu yer kullanılmalıdır. Exception'ı ilk argüman olarak verip logger.LogError(ex, "Saving answers for session {SessionId} failed", sessionId) yazın. ex.Message'ı metnin içine koymak exception tipini, stack trace'i ve inner exception'ları çöpe atar ve her farklı mesajı yeni bir şablona dönüştürür. Bir exception'ı bir kez, onu gerçekten ele alan yerde loglayın. Her katmanda loglayıp yeniden fırlatmak aynı stack trace'in beş kopyasını üretir ve hata sayısı artık hiçbir şey ifade etmez.

Serilog'u ASP.NET Core'a bağlamak

Serilog.AspNetCore dokümantasyonundaki iki aşamalı kurulumu kullanıyorum. Program.cs'in ilk satırından itibaren bir bootstrap logger vardır; böylece yapılandırma okunurken yaşanan bir çökme de loglanır. Host oluşturulduğunda bu logger'ın yerini gerçek logger alır:

using Serilog;
using Serilog.Formatting.Compact;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateBootstrapLogger();

try
{
    var builder = WebApplication.CreateBuilder(args);

    builder.Services.AddSerilog((services, lc) => lc
        .ReadFrom.Configuration(builder.Configuration)
        .ReadFrom.Services(services)
        .Enrich.FromLogContext()
        .Enrich.WithProperty("Service", "exam-api")
        .WriteTo.Console(new CompactJsonFormatter()));

    var app = builder.Build();
    app.UseSerilogRequestLogging();
    // ... the rest of the pipeline and the endpoints
    app.Run();
}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush();
}

AddSerilog, uygulamadaki ve framework'teki her ILogger<T> çağrısını Serilog üzerinden yönlendirir; bu yüzden mevcut kod değişmez. Minimum seviyeler yapılandırmada durur; yani yeniden derlemeye gerek kalmadan ortamdan ortama farklı olabilir:

"Serilog": {
  "MinimumLevel": {
    "Default": "Information",
    "Override": {
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.EntityFrameworkCore": "Warning",
      "System.Net.Http.HttpClient": "Warning"
    }
  }
}

İstek başına bir olay ve her olayda bağlam

ASP.NET Core varsayılan olarak her istek için birkaç Information olayı yazar. UseSerilogRequestLogging() bunların yerine metodu, path'i, status code'u ve geçen süreyi taşıyan tek bir tamamlanma olayı koyar; yukarıdaki override'ın Microsoft.AspNetCore'u Warning seviyesine indirmesinin nedeni budur. Bu tek olay çoğu incelemenin omurgasıdır, bu yüzden zenginleştirmeye değer:

app.UseSerilogRequestLogging(options =>
{
    options.GetLevel = (http, elapsedMs, ex) =>
        ex is not null || http.Response.StatusCode >= 500 ? LogEventLevel.Error
        : http.Request.Path.StartsWithSegments("/health") ? LogEventLevel.Verbose
        : elapsedMs > 1000 ? LogEventLevel.Warning
        : LogEventLevel.Information;
});

app.UseAuthentication();

// after authentication, so the user and tenant are known
app.Use(async (http, next) =>
{
    var userId = http.User.FindFirst("sub")?.Value;
    var tenantId = http.User.FindFirst("tenant_id")?.Value;

    var diagnostics = http.RequestServices.GetRequiredService<IDiagnosticContext>();
    diagnostics.Set("UserId", userId);          // for the completion event
    diagnostics.Set("TenantId", tenantId);

    using (LogContext.PushProperty("UserId", userId))     // for every event inside the request
    using (LogContext.PushProperty("TenantId", tenantId))
    {
        await next(http);
    }
});

İki mekanizma gereksiz bir tekrar gibi görünür, ama değildir. LogContext.PushProperty, using bloğu içinde yazılan her olaya bir property ekler; ancak request logging middleware'i tamamlanma olayını bu blok sona erdikten sonra yazar. IDiagnosticContext tam olarak bu olay için vardır. İkisi birlikte kullanıldığında bir isteğin özet dâhil her satırı kullanıcıya ve tenant'a göre filtrelenebilir.

Claim adları kimlik sağlayıcınıza bağlıdır. Bağlı kaldığım kural, bunların insan değil tanımlayıcı olmasıdır: opak bir kullanıcı id'si; asla bir telefon numarası ya da isim değil. Geliştirmekte olduğum multi-tenant platformda tenant id'si istek başına bir kez çözümlenir ve loglarda ve trace'lerde yer alabilir; ama metrik etiketi olarak kullanılamaz, çünkü orada zaman serisi sayısını tenant sayısıyla çarpar.

Seviyeler ancak ekip üzerlerinde anlaşırsa bir anlam taşır

Code review'da savunduğum tanımlar kısadır. Error, birinin buna bakması gerektiği anlamına gelir. Warning, bir şeyin aksadığı ama ele alındığı anlamına gelir: bir yeniden deneme başarılı oldu, bir fallback kullanıldı, bir istek yavaştı. Information iş olaylarını ve istek başına tek özeti kaydeder. Debug ve Verbose canlı ortamda kapalıdır; bir inceleme gerektirdiğinde yapılandırma üzerinden, her seferinde tek bir namespace için açılır. Bir yapılandırma değişikliği bile fazla yavaş kaldığında, MinimumLevel.ControlledBy(...)'ye verilen bir LoggingLevelSwitch, kimliği doğrulanmış bir admin endpoint'inden çalışma anında değiştirilebilir ve inceleme bittiğinde eski hâline döndürülebilir.

Örnekleme, insanların ya fazla harcadığı ya da kanıt kaybettiği yerdir. Hataları örneklemem; gerçek kullanıcı trafiği için istek özetini de örneklemem, çünkü bir inceleme bu olaylardan başlar. Attığım şey bilinen gürültüdür: health check'ler (yukarıdaki GetLevel kuralı onları minimum seviyenin altındaki Verbose'a gönderir), readiness probe'ları ve çok log üreten framework kategorileri. Bir filtrenin daha spesifik olması gerektiğinde Serilog.Expressions onu metin olarak yazmanıza izin verir; örneğin Filter.ByExcluding("RequestPath like '/health%'"). İstatistiksel örnekleme trace'lere aittir; OpenTelemetry araçları zaten bunun için tasarlanmıştır.

Sink'ler: olaylar nereye gider

Container'larda standart çıktıya kompakt JSON yazar ve toplama işini platforma bırakırım. Uygulama log backend'inden habersiz kalır ve o backend'i değiştirmek bir operasyon kararı olur. Küçük bir ekip için Seq, geliştirme sırasında ve mütevazı canlı ortam kurulumlarında yapılandırılmış olayları okumak için hoş bir yerdir; sink'i olayları batch'ler hâlinde gönderir, bu yüzden yavaş bir ağ istekleri yavaşlatmaz.

Bir SQL tablosu yalnızca hatalar için makul bir yer olabilir; özellikle ekip zaten her gün SQL Server ile çalışıyorsa ve elinde başka bir şey yoksa. Minimum seviyesi olan bir alt sink hacmi küçük tutar:

.WriteTo.Console(new CompactJsonFormatter())
.WriteTo.MSSqlServer(
    connectionString: builder.Configuration.GetConnectionString("Logs"),
    sinkOptions: new MSSqlServerSinkOptions { TableName = "ErrorLog", AutoCreateSqlTable = true },
    restrictedToMinimumLevel: LogEventLevel.Error)

İki uyarı. Loglama, anlattığı iş yüküyle rekabet edemesin diye ayrı bir veritabanı ya da en azından ayrı bir connection string kullanın. Ve bir kesinti sırasında hataların, tam da veritabanının en çok baskı altında olduğu anda toplu hâlde geldiğini unutmayın. Tablo işi kolaylaştırır ama bir gözlemlenebilirlik platformunun yerini tutmaz.

Logları trace'lerle ilişkilendirmek

Loglar size tek bir süreç içinde ne olduğunu söyler; trace'ler ise bir isteğin süreçler arasında nasıl ilerlediğini. Aynı id'yi paylaştıklarında çok daha faydalı hâle gelirler. Serilog 3.1'den beri her olay Activity.Current'ın trace ve span id'lerini yakalar ve kompakt JSON formatter'ı bunları @tr ve @sp olarak yazar. OpenTelemetry tracing'i açtığınızda bu id'ler, isteğin dokunduğu her servisle paylaşılan gerçek W3C trace id'leri olur:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(r => r.AddService("exam-api"))
    .WithTracing(t => t
        .AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddOtlpExporter());

Bu, Minimal APIs notunda açık kalan bir halkayı kapatıyor. ProblemDetails kurulumunun her hata yanıtına koyduğu traceId, o isteğin her log olayında duran id'nin ta kendisidir. Bir kullanıcı ya da destek ekibinden bir çalışma arkadaşı size hata body'sini gönderir; siz trace id'sini log aramasına yapıştırır ve isteğin tamamını servisler boyunca görürsünüz. Logların da OTLP üzerinden taşınmasını istiyorsanız, Serilog.Sinks.OpenTelemetry onları trace'lerle aynı collector'a export eder.

Kişisel veriler ve gizli bilgiler

Loglar veritabanlarından daha geniş çapta kopyalanır ve daha az özenle saklanır; bu yüzden onları hassas verinin asla ulaşmaması gereken bir yer olarak ele alırım. Code review'da kontrol ettiğim liste:

• Asla loglamayın: parolalar, token'lar, Authorization ya da Cookie header'ları, connection string'ler, API anahtarları ve tek kullanımlık kodlar.
• Kaçının: telefon numaraları, e-posta adresleri, ulusal kimlik numaraları ve tam adlar. Dahili id'yi loglayın ve gerektiğinde kişiyi, veritabanı için geçerli olan erişim kontrolleriyle bulun.
• Varsayılan olarak loglamayın: request ya da response body'lerinin tamamı. Belirli bir inceleme için body gerektiğinde, sınırlı bir süre boyunca küçültülmüş bir biçimini loglayın.
• Yalnızca geliştirmede kullanın: EF Core'daki EnableSensitiveDataLogging(); SQL parametre değerlerini loglara yazar.
• Bilinçli olarak destructure edin. Bir tipin loglanması gerekiyorsa, Destructure.ByTransforming<T>(...) hangi alanların güvenli olduğuna bir kez karar verir.

Saklama süresi de aynı kararın parçasıdır. Ayrıntılı logları, onlarla gerçekten inceleme yaptığınız süre boyunca tutun; daha uzun değil.

Logların maliyeti

Loglamanın bir bedeli vardır: süreç içinde CPU ve bellek ayırmaları (allocation), ağ, depolama, indeksleme ve insanların okumaya harcadığı zaman. On binlerce öğrenci aynı anda aktifken istek başına tek bir Information olayı bile çok fazla veri demektir ve bir döngünün içindeki tek bir LogInformation geri kalan her şeyden ağır basabilir. Arada bir olayları şablona göre sayarım (yapılandırılmış loglarla bu çok kolaydır) ve ilk ona bakarım. Olağan bulgular, Information seviyesinde bırakılmış bir framework kategorisi, sıcak bir döngüye sızmış bir debug satırı ve her çağrıda destructure edilen büyük bir nesnedir. Bu üçünü düzeltmek genellikle herhangi bir örnekleme planından daha fazla işe yarar.

Loglarınız gürültülü geliyor ve yine de bir arıza sırasında sorduğunuz soruları yanıtlamıyorsa, bu tam da üstlendiğim türden bir backend işi. Bir sonraki not, bir servisin raporladıklarından, asla birbirine karıştırmaması gereken şeye geçiyor: EF Core filtreleri ve row-level security ile korunan, paylaşılan bir PostgreSQL veritabanındaki tenant'lar.

Bu not İngilizce ve Farsça olarak da yayımlandı: İngilizce · Farsça.