Neyi Loglamalı, Neyi Loglamamalı: .NET'te Logging Stratejisi ve İyi Bir Log Event'inin Anatomisi

Sürüm notu: Bu yazıdaki kodlar .NET 10 ile derlenip denenmiştir.

Önce Tahmin Et

Bookstore'un sipariş endpoint'inde, stokta yalnız 1 adet kalan bir kitaptan 3 adet isteyen bir sipariş geliyor. Service exception'ı yakalıyor, LogError ile logluyor ve throw; ile yeniden fırlatıyor. Uygulamada global exception handler da açık. Bu tek başarısız istek için log'da kaç tane fail satırı görürsün? Bir de şunu düşün: logger.LogInformation($"Order {order.Id} created, total {order.Total}") satırı, Türkçe bölge ayarlı bir makinede 91 liralık siparişin tutarını log'a nasıl yazar?

İki sorunun cevabı da bu yazının ortasında, gerçek çıktılarla duruyor. Önce bir adım geri çekilip log'un ne için yazıldığına bakalım.

Log'u Kim Okuyor?

ASP.NET Core Web API (Application Programming Interface) serisinin "ASP.NET Core'da Logging: ILogger, Log Seviyeleri, Structured Logging ve Serilog" yazısında ILogger<T>'yi, category'yi, log seviyelerini, appsettings filtrelerini ve message template'i kurmuştuk. Bu seri o temelin üstüne kuruluyor; mekaniği tekrar anlatmayacağım. Bu yazının sorusu başka: o mekanikle neyi yazmalısın?

Bir log satırının üç ayrı okuru var ve her biri başka bir şey arıyor:

• Geliştirici (debug): "Bu sipariş neden reddedildi, hangi kitap, kaç adet istendi?" Ayrıntı ister, ama yalnız sorunlu istek için.
• Operasyon (incident): Gece 03:00'te alarm çaldığında "son 15 dakikada kaç sipariş ödeme hatası aldı, hepsi aynı gateway'den mi?" diye sorar. Sayılabilir, filtrelenebilir alanlar ister.
• Güvenlik (audit): "Bu müşterinin hesabında kim, ne zaman, hangi işlemi yaptı?" Değişmeyen, eksiksiz kayıt ister; parola ya da kart numarası görmek istemez.

Bir log satırını yazarken "bunu kim, hangi soruyla okuyacak?" diye sorarsan gereksiz satırların çoğu kendiliğinden elenir. "Entering method X" satırını bu üç okurdan hiçbiri istemez.

Log tek araç da değil. Observability (gözlemlenebilirlik) üç sinyalden oluşur ve her biri farklı bir soruya cevap verir. Metric, sayıları zaman içinde toplar: "dakikada kaç sipariş, p99 süre kaç milisaniye?" Ucuzdur, çünkü tek tek olayları değil toplamları saklar. Trace, tek bir isteğin servisler arasındaki yolculuğunu ve her adımın süresini gösterir. Log ise tek bir olayın ayrıntısını anlatır: hangi müşteri, hangi kitap, hangi sebep. "Dakikada kaç sipariş geldi?" sorusunu log satırı sayarak cevaplamaya çalışıyorsan yanlış aracı kullanıyorsun; o bir metric. Metric ve trace tasarımını ilerideki DevOps › Observability serisine bırakıyoruz; bu seride log tarafındayız.

Kötü Log Satırlarının Anatomisi

Gerçek projelerde sık gördüğüm bir service ile başlayalım. Derleniyor, çalışıyor, log da yazıyor:

public sealed class BadOrderService(ILogger<BadOrderService> logger, Inventory inventory, PaymentGateway payments)
{
    public async Task<Order> PlaceOrderAsync(PlaceOrderRequest request, string cardLast4)
    {
        logger.LogInformation("Entering PlaceOrderAsync");
        logger.LogInformation($"Placing order for customer {request.CustomerId} with {request.Lines.Count} lines");
        try
        {
            foreach (OrderLine line in request.Lines)
            {
                inventory.Reserve(line.Isbn, line.Quantity);
            }

            decimal total = request.Lines.Sum(l => l.Quantity * l.UnitPrice);
            await payments.ChargeAsync(request.CustomerId, total, cardLast4);
            Order order = new(Guid.CreateVersion7(), request.CustomerId, total);

            logger.LogInformation($"Order {order.Id} created, total {order.Total}");
            logger.LogInformation("Exiting PlaceOrderAsync");
            return order;
        }
        catch (Exception ex)
        {
            logger.LogError(ex, $"Error: {ex.Message}");
            throw;
        }
    }
}

Başarılı bir siparişte konsola düşen dört satır:

info: Bookstore.Orders.BadOrderService[0]
      Entering PlaceOrderAsync
info: Bookstore.Orders.BadOrderService[0]
      Placing order for customer 42 with 1 lines
info: Bookstore.Orders.BadOrderService[0]
      Order 01a1b8de-2cde-7e83-8821-26cda3b00925 created, total 91,0
info: Bookstore.Orders.BadOrderService[0]
      Exiting PlaceOrderAsync

Beş log çağrısının her birinde ayrı bir sorun var. "Entering" ve "Exiting" satırları hiçbir bilgi taşımıyor; method'un çağrıldığını zaten bir sonraki satır kanıtlıyor. Bunlar trace'in işi ve production'da her siparişte iki satır, yani iki kat depolama demek. "Placing order" ile "Order created" aynı olayın iki ucu; ilki gereksiz. Köşeli parantezdeki [0] EventId: hiçbir satırın kimliği yok, "bütün sipariş oluşturma olaylarını getir" sorgusunu ancak metin aramasıyla yapabilirsin. En sinsisi de 91,0: interpolation string'i o anki culture ile biçimlendiriyor, makine Türkçe olduğu için ondalık ayırıcı virgül oldu. Aynı kod İngilizce ayarlı bir container'da 91.0 yazar ve iki ortamın log'larını aynı sorguyla tarayamazsın.

İyi Bir Log Event'i: Sabit Template, Anlamlı Property, EventId

Aynı akışı üç event'e indirelim. Her event'in sabit bir kimliği, sabit bir message template'i ve sorgulanabilir property'leri var:

public sealed class OrderService(ILogger<OrderService> logger, Inventory inventory, PaymentGateway payments)
{
    private static readonly EventId OrderPlaced = new(1001, nameof(OrderPlaced));
    private static readonly EventId OrderRejected = new(1002, nameof(OrderRejected));
    private static readonly EventId PaymentRetried = new(1003, nameof(PaymentRetried));

    public async Task<Order?> PlaceOrderAsync(PlaceOrderRequest request, string cardLast4)
    {
        try
        {
            foreach (OrderLine line in request.Lines)
            {
                inventory.Reserve(line.Isbn, line.Quantity);
            }
        }
        catch (OutOfStockException ex)
        {
            // beklenen iş sonucu: Information, stack trace yok, çağıran 409 alır
            logger.LogInformation(OrderRejected,
                "Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})",
                request.CustomerId, "OutOfStock", ex.Isbn, ex.Requested, ex.Available);
            return null;
        }

        decimal total = request.Lines.Sum(l => l.Quantity * l.UnitPrice);
        int attempts = await payments.ChargeAsync(request.CustomerId, total, cardLast4);
        if (attempts > 1)
        {
            // kendini toparladı: Warning
            logger.LogWarning(PaymentRetried,
                "Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts",
                request.CustomerId, attempts);
        }

        Order order = new(Guid.CreateVersion7(), request.CustomerId, total);
        logger.LogInformation(OrderPlaced,
            "Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}",
            order.Id, order.CustomerId, request.Lines.Count, order.Total);
        return order;
    }
}

Structured log'un değerini görmek için konsolu JSON (JavaScript Object Notation) formatter ile çalıştırdım (--Logging:Console:FormatterName=json). İki başarılı sipariş ve bir stok reddinin gerçek çıktısı:

{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order 01a1b8de-8d15-7651-b472-6d4f3064e0f6 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d15-7651-b472-6d4f3064e0f6","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}
{"EventId":1003,"LogLevel":"Warning","Category":"Bookstore.Orders.OrderService","Message":"Payment for customer 42 succeeded after 2 attempts","State":{"CustomerId":42,"PaymentAttempts":2,"{OriginalFormat}":"Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts"}}
{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order 01a1b8de-8d20-7a0a-98b7-bf4909171000 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d20-7a0a-98b7-bf4909171000","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}
{"EventId":1002,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order rejected for customer 42: OutOfStock on 978-0321125217 (requested 3, available 1)","State":{"CustomerId":42,"RejectReason":"OutOfStock","Isbn":"978-0321125217","Requested":3,"Available":1,"{OriginalFormat}":"Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})"}}

Burada dört şey var. Birincisi, State içindeki her placeholder ayrı bir property: Seq, Elasticsearch ya da herhangi bir log aracında CustomerId = 42 ya da OrderTotal > 500 diye sorgulayabilirsin. İkincisi, {OriginalFormat} bütün siparişlerde aynı; bu, "aynı türden olaylar" gruplamasının anahtarı. Üçüncüsü, OrderTotal aynı Türkçe makinede bu kez 91.0: message template biçimlendirmesi culture'dan bağımsız. Dördüncüsü, EventId artık 1001, 1002, 1003; template metnini değiştirsen bile olayın kimliği sabit kalıyor.

Property adları da bir contract. CustomerId'yi bir yerde CustomerId, başka bir yerde customerId, üçüncü yerde UserId yazarsan, "bu müşterinin bütün log'ları" sorgusu üç ayrı field'a bakmak zorunda kalır. Ekip içinde ortak bir sözlük tut: OrderId, CustomerId, Isbn her yerde aynı yazılsın. Bir sonraki yazıda bu sözlüğü bir event kataloğuna dönüştüreceğiz.

"Tek event = tek olay" kuralının pratik karşılığı şu: bir log satırı okunduğunda "ne oldu?" sorusunun cevabı tek cümle olmalı. "Order placed" bir olay. "Entering method" bir olay değil, bir kod konumu.

Hangi Seviyede Ne?

Seviyelerin tanımını Web API serisinde gördük. Burada kararın kendisine bakalım, çünkü yanlış seviye hem gürültü hem de kaçırılan alarm demek:

En sık yapılan hata, iş kuralı ihlalini Error diye loglamak. Stok yetmemesi bir hata değil, uygulamanın beklediği ve 409 ile cevapladığı bir durum. Onu Error yaparsan hata oranı alarmın her kampanya gününde çalar ve ekip bir süre sonra alarmı görmezden gelmeye başlar. Kendine sor: "Bu satır gece 03:00'te birini uyandırmalı mı?" Cevap hayırsa Error değildir.

Warning'in sınırı da önemli. Ödemenin ikinci denemede geçmesi tek başına sorun değil, ama oranı artıyorsa gateway'de bir şeyler kötüye gidiyordur. Warning, "şimdi aksiyon gerekmez ama sayısı artarsa bak" demek.

Exception'ı Bir Kez Logla

Baştaki ilk soruya dönelim. BadOrderService'e stokta olmayan bir sipariş gönderdiğimde konsola düşenler (yollar PathMap ile kısaltıldı):

info: Bookstore.Orders.BadOrderService[0]
      Entering PlaceOrderAsync
info: Bookstore.Orders.BadOrderService[0]
      Placing order for customer 42 with 1 lines
fail: Bookstore.Orders.BadOrderService[0]
      Error: Not enough stock for 978-0321125217: requested 3, available 1
      Bookstore.Orders.OutOfStockException: Not enough stock for 978-0321125217: requested 3, available 1
         at Bookstore.Orders.Inventory.Reserve(String isbn, Int32 quantity) in /src/Bookstore.Orders/Domain.cs:line 32
         at Bookstore.Orders.BadOrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/BadOrderService.cs:line 13
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      Bookstore.Orders.OutOfStockException: Not enough stock for 978-0321125217: requested 3, available 1
         at Bookstore.Orders.Inventory.Reserve(String isbn, Int32 quantity) in /src/Bookstore.Orders/Domain.cs:line 32
         at Bookstore.Orders.BadOrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/BadOrderService.cs:line 13
         at Program.<>c.<<<Main>$>b__0_0>d.MoveNext() in /src/Bookstore.Orders/Program.cs:line 14

Cevap iki: tek bir başarısız istek için iki fail satırı, iki stack trace. Katman sayısı arttıkça bu sayı da artar; repository, service ve controller'ın her biri "logla ve fırlat" yaparsa bir hata log'da dört kez görünür. Hata oranı dashboard'u gerçeğin dört katını gösterir, alarm eşiği anlamsızlaşır ve incident sırasında "bunlar dört ayrı hata mı, tek hata mı?" sorusuyla vakit kaybedersin. Üstelik bu örnekte asıl sorun hiç Error değil: stok yetmemesi 500 ile değil 409 ile cevaplanmalıydı.

Kural basit: bir exception'ı ya logla ve orada ele al, ya da loglamadan fırlat ve en üstteki tek bir yerde logla. ASP.NET Core Web API serisinin "Global Hata Yönetimi: Exception Middleware ve ProblemDetails" yazısında kurduğumuz global handler o tek yer. OrderService'te ödeme gateway'i çöktüğünde service hiçbir şey loglamıyor, exception'ı yukarı bırakıyor:

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      Bookstore.Orders.PaymentGatewayException: Payment gateway timed out after 3 attempts
         at Bookstore.Orders.PaymentGateway.ChargeAsync(Int32 customerId, Decimal amount, String cardLast4) in /src/Bookstore.Orders/Domain.cs:line 47
         at Bookstore.Orders.OrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/OrderService.cs:line 28
         at Program.<>c.<<<Main>$>b__0_1>d.MoveNext() in /src/Bookstore.Orders/Program.cs:line 17

Tek satır, tek stack trace. Peki bağlam ne olacak; hangi müşterinin ödemesi düştü? Bunu exception'ı tekrar loglayarak değil, isteğin bütün log'larına eklenen bir scope ya da trace id ile çözüyoruz. Bunun tam hâlini serinin "Correlation ID ve Trace Context" yazısında kuracağız.

Bir istisna var: exception'ı yakalayıp ele alıyorsan, yani fırlatmıyorsan, o noktada loglamak doğru. OutOfStockException'ı yakalayıp 409 dönen OrderService bunu yapıyor, üstelik stack trace olmadan, çünkü beklenen bir durumun stack trace'i kimseye bir şey anlatmaz.

String Interpolation ve CA2254

$"Order {order.Id} created" yazdığında derleyici önce string'i oluşturur, logger'a hazır bir metin gider. Template her siparişte farklı olduğu için gruplama imkânsızlaşır, property'ler kaybolur. Yukarıdaki kötü service'in JSON çıktısındaki karşılığı:

{"EventId":0,"LogLevel":"Information","Category":"Bookstore.Orders.BadOrderService","Message":"Order 01a1b8de-8d2c-7918-a521-d500730598b6 created, total 91,0","State":{"{OriginalFormat}":"Order 01a1b8de-8d2c-7918-a521-d500730598b6 created, total 91,0"}}

State içinde OrderId yok; {OriginalFormat} ise her siparişte farklı bir metin. Bu satır structured logging'in bütün getirisini öldürüyor.

Bunu yakalayan analyzer kuralı CA2254 ("Template should be a static expression"). .NET 10'da varsayılan olarak yalnız suggestion seviyesinde açık, yani komut satırı build'inde görünmez. Proje köküne bir .editorconfig koyup seviyesini yükseltiyorum; yanına CA1848 ve CA1873'ü de ekliyorum:

root = true
[*.cs]
dotnet_diagnostic.CA2254.severity = warning
dotnet_diagnostic.CA1848.severity = warning
dotnet_diagnostic.CA1873.severity = warning

dotnet build çıktısından BadOrderService'in 8. satırına ait üç uyarı:

BadOrderService.cs(8,9): warning CA1848: For improved performance, use the LoggerMessage delegates instead of calling 'LoggerExtensions.LogInformation(ILogger, string?, params object?[])' (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca1848)
BadOrderService.cs(8,31): warning CA1873: Evaluation of this argument may be expensive and unnecessary if logging is disabled (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca1873)
BadOrderService.cs(8,31): warning CA2254: The logging message template should not vary between calls to 'LoggerExtensions.LogInformation(ILogger, string?, params object?[])' (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca2254)

CA2254 yalnız interpolation ve concatenation olan satırlarda çıkıyor; OrderService için hiç üretilmedi. CA1848 ve CA1873 ise OrderService'te de çıktı: ikisi de performansla ilgili ve "LogInformation extension method'u yerine source-generated LoggerMessage kullan" diyor. Seviye kapalıyken bile argümanların hesaplanması, boxing ve params object[] allocation'ı bir sonraki yazının konusu. Bu yüzden ekipte en azından CA2254'ü warning yapmanı öneririm; CA1848'i ise sıcak yollardaki (hot path) kod için düşün.

Üretimde Dikkat

Log'un bir maliyeti var ve bu maliyet satır sayısıyla doğru orantılı. Kötü service başarılı her siparişte dört satır yazıyordu, iyi service bir satır yazıyor. Günde 200.000 siparişte bu 800.000 ile 200.000 satır arasındaki fark; log aracın ingestion'a göre ücretlendiriyorsa doğrudan faturaya yansır. Log hacmini ve maliyetini ölçmeyi serinin "Log Level'ları ve Maliyet" yazısında ayrıntılı yapacağız.

Hangi event'in ne kadar sık yazıldığını bilmek için EventId en iyi araç. Haftada bir "en çok yazılan 10 EventId" sorgusu çalıştır; listenin başında bir "Entering" ya da "Cache hit" satırı görüyorsan seviyesini düşürme vakti gelmiştir.

Log'a ne girdiğini kontrol etmek de bir sorumluluk. Kart numarası, parola, token, TC (Türkiye Cumhuriyeti) kimlik numarası ve açık adres log'a hiç girmemeli. Burada sadece cardLast4'ü bile loglamadık; o bilginin hiçbir okurun sorusuna cevap vermediğini fark etmek yeterli. Güvenlik tarafında neyin loglanması gerektiğini (başarısız login, yetki reddi, kritik iş işlemleri) OWASP (Open Worldwide Application Security Project) Top 10 üzerine kurulu Web Güvenliği serisinin "OWASP A09: Security Logging and Alerting Failures" yazısında konuştuk; burada tekrar etmiyorum. Hassas veriyi maskelemenin teknik tarafı, yani redaction ve data classification ise bu serinin yedinci yazısında.

Sık Düşülen Tuzaklar

Birincisi, her şeyi Information'da loglamak. Seviye ayrımı yoksa filtre de yok; production'da ya hepsini görürsün ya hiçbirini. "Cache hit" ile "Order placed" aynı seviyede olmamalı.

İkincisi, exception'ı message'a gömmek: logger.LogError($"Error: {ex.Message}"). Stack trace kaybolur, exception tipi kaybolur. Exception her zaman ilk parametre olarak verilir: logger.LogError(ex, "Payment failed for order {OrderId}", orderId).

Üçüncüsü, aynı placeholder adını farklı anlamlarda kullanmak. Bir event'te {Id} sipariş id'si, diğerinde müşteri id'si ise sorgu sonuçların anlamsız olur. Genel adlar (Id, Name, Value) yerine OrderId, CustomerId gibi bağlamı taşıyan adlar kullan.

Dördüncüsü, bütün request object'ini loglamak: logger.LogInformation("Request: {@Request}", request). Bugün request'te üç alan var, yarın birisi oraya e-posta ve telefon ekler ve fark etmeden kişisel veri loglamaya başlarsın. Neyi logladığını açıkça seç.

Beşincisi, log'u kontrol akışı için kullanmak. "Bu satır log'da görünüyorsa sipariş tamamlanmıştır" diye bir raporlama işi kurulursa log seviyesi değiştiğinde iş mantığı bozulur. Log'lar gözlem içindir; iş verisi veritabanında durur.

Küçük Bir Deneme

★☆☆ Kötü service'teki Placing order satırını kaldır, Order created satırını message template'e çevir ve OrderId ile OrderTotal'ı property olarak yaz. JSON console çıktısında State içinde iki property gördüğünü ve tutarın noktayla yazıldığını doğrula.

★★☆ OrderService'e bir OrderCancelled event'i ekle (EventId 1004). Hangi seviyede olmalı, kendin karar ver ve gerekçeni yaz. Müşteri iptali ile sistemin ödeme zaman aşımı yüzünden yaptığı iptal aynı seviyede mi olmalı?

★★★ BadOrderService'in önüne bir controller ve bir repository katmanı ekle; her katman "logla ve fırlat" yapsın. Stokta olmayan bir sipariş için kaç fail satırı çıktığını say. Sonra loglamayı yalnız global handler'a bırak ve sayıyı tekrar karşılaştır.

Bu yazıda neyi loglayacağımıza karar verdik. Bir sonraki yazıda aynı event'leri ucuza yazmayı konuşacağız: LoggerMessage source generator'ı, IsEnabled kontrolü, kapalı seviyede bile yapılan boxing ve allocation, BenchmarkDotNet ile ölçülmüş farklar ve bu yazıdaki üç event'i tek bir event kataloğunda toplamak.