Log Level'ları ve Maliyet: Sampling, Buffering ve Production'da Log Seviyesini Canlı Değiştirmek

Sürüm notu: Bu yazıdaki kodlar .NET 10, Microsoft.Extensions.Telemetry 10.11, Microsoft.AspNetCore.Diagnostics.Middleware 10.11 ve Serilog.AspNetCore 10.0 ile derlenip denenmiştir.

Önce Tahmin Et

Bookstore'un katalog API'sine (Application Programming Interface) builder.Logging.AddTraceBasedSampler() satırını ekliyorsun. OpenTelemetry tracing kurulu değil; yalnız bu tek satır var. Ardından dışarıdan hiçbir header göndermeyen sıradan bir istek atıyorsun ve istek veritabanı zaman aşımı yüzünden 503 ile dönüyor. Endpoint'teki LogError satırı konsola düşer mi?

İkinci soru: sampling'i "Probability": 0.1 olan tek bir kuralla açıyorsun, kuralda ne category ne de log level var. 1000 istekte 10 tane hata oluşuyor. Log'da kaç Error görürsün?

İki cevap da yazının içinde, gerçek koşulardan. İkisi de "log'u ucuzlatayım derken en değerli satırı kaybetmek" ile ilgili.

Log Hacminin Faturası

Log'un maliyeti üç kalemden oluşur. Birincisi ingestion: log aracının çoğu, içeri aldığı veri miktarına göre ücretlendirir ya da lisansında bir GB sınırı vardır. İkincisi saklama: aynı veriyi 30 gün mü, 90 gün mü tuttuğun disk ve faturayı doğrudan çarpar. Üçüncüsü sorgu: hacim büyüdükçe "son bir saatteki hatalar" sorgusu yavaşlar, incident sırasında beklediğin her saniye pahalıdır. Uygulama tarafında ise log yazmak CPU (Central Processing Unit), bellek ve I/O (Input/Output) harcar.

Tahmin yerine ölçelim. Örnek uygulamada /books/{id} endpoint'i her istekte iki Debug, bir Information yazıyor; her 50. kitapta bir Warning, her 100. kitapta bir Error var:

public sealed class BookService(ILogger<BookService> logger)
{
    public Book GetBook(int id)
    {
        Log.CacheLookup(logger, id);
        Log.CacheMiss(logger, id);
        if (id % 100 == 0)
        {
            throw new TimeoutException($"Database query for book {id} timed out");
        }
        if (id % 50 == 0)
        {
            Log.PriceServiceSlow(logger, id, 1240);
        }
        Log.BookViewed(logger, id);
        return new Book(id, $"Book {id}", 30m + id % 7);
    }
}

Log class'ı serinin "High-Performance Logging" yazısındaki gibi source-generated method'lardan oluşuyor (EventId 2001–2005). Uygulamayı JSON (JavaScript Object Notation) console formatter ile dört farklı seviye ayarında başlattım, her seferinde 1000 istek attım ve çıktıyı seviye seviye saydım:

dotnet Bookstore.Catalog.dll --Logging:Console:FormatterName=json \
    --Logging:LogLevel:Default=Debug --Logging:LogLevel:Microsoft.AspNetCore=Debug
./load.sh 17445 1000
python3 count.py vol2_A.log

İlk satırla üçüncü satır arasında 25 kat fark var ve kodda tek bir değişiklik yok; yalnız iki configuration değeri değişti. Günde 5 milyon istek alan bir API'de bu, yaklaşık 31 GB ile 1,2 GB arasındaki fark demek. Faturanın nereden geldiğini görmek için ikinci satırın dökümüne baktım:

1000 ('Information', 'Microsoft.AspNetCore.Hosting.Diagnostics', 1)
1000 ('Information', 'Microsoft.AspNetCore.Routing.EndpointMiddleware', 0)
1000 ('Information', 'Microsoft.AspNetCore.Routing.EndpointMiddleware', 1)
1000 ('Information', 'Microsoft.AspNetCore.Hosting.Diagnostics', 2)
990 ('Information', 'Bookstore.Catalog.BookService', 2003)
990 ('Information', 'Microsoft.AspNetCore.Http.Result.OkObjectResult', 1)
990 ('Information', 'Microsoft.AspNetCore.Http.Result.OkObjectResult', 3)

İstek başına yedi Information satırının altısı framework'ten geliyor: "Request starting", "Executing endpoint", "Executed endpoint", "Request finished" ve sonucun yazılmasıyla ilgili iki satır. Bizim iş event'imiz, yani BookViewed, yedide bir. Proje template'indeki "Microsoft.AspNetCore": "Warning" satırının neden orada olduğu bu tabloda görünüyor. İstek özetini yine de istiyorsan istek başına tek satır yazan bir alternatif seç: serinin "Serilog Derinlemesine" yazısındaki UseSerilogRequestLogging ya da HTTP (Hypertext Transfer Protocol) isteklerini loglamayı anlatan "HTTP Logging" yazısındaki CombineLogs.

Debug satırında ise 12.007 satırın 10.000'den fazlası Kestrel bağlantı event'leri ve routing eşleşmeleri. Production'da Debug'ı "bir süreliğine" açık bırakmanın faturası buradan gelir.

Random Probabilistic Sampling

Filtre bir log'u ya tamamen yazar ya hiç yazmaz. Sampling ise arada bir oran seçmeni sağlar: BookViewed event'inin yüzde 10'u, trendi görmek için çoğu zaman yeterlidir. Sampling, .NET 9 döneminde Microsoft.Extensions.Telemetry paketinin 9.3 sürümüyle geldi. Örnek uygulamada demo modlarını configuration'dan seçiyorum:

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
string mode = builder.Configuration["Demo:Mode"] ?? "plain";

if (mode == "random")
{
    builder.Logging.AddRandomProbabilisticSampler(builder.Configuration);
}
else if (mode == "trace")
{
    builder.Logging.AddTraceBasedSampler();
}
else if (mode == "buffer")
{
    builder.Logging.AddPerIncomingRequestBuffer(builder.Configuration.GetSection("Logging"));
}

Kural appsettings.json'da:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  },
  "AllowedHosts": "*",
  "RandomProbabilisticSampler": {
    "Rules": [
      {
        "CategoryName": "Bookstore.Catalog",
        "LogLevel": "Information",
        "Probability": 0.1
      }
    ]
  }
}

1000 isteğin gerçek sonucu:

Information      98 lines     24976 bytes
Warning          10 lines      3248 bytes
Error            10 lines      6563 bytes
Total           118 lines     34787 bytes

990 BookViewed event'inden 98'i yazıldı; Warning ve Error satırlarının hepsi duruyor. Kuralın LogLevel alanı "bu seviye ve altı" demek: Information yazdığın için Warning ve Error kuralın dışında kaldı. Bir kayıt için birden fazla kural eşleşirse en uzun category öneki kazanır, eşitlikte listedeki son kural seçilir; hiçbir kural eşleşmezse kayıt olduğu gibi yazılır.

Bu bölümü yazarken bir şeye takıldım. Microsoft Learn'deki "runtime'da değiştirme" örneği RandomProbabilisticSampler bölümünü Logging section'ının altına koyuyor. Ben de önce öyle yaptım ve 990 Information satırının hepsini gördüm; sampler hiç çalışmadı, hata da vermedi. AddRandomProbabilisticSampler(builder.Configuration) 10.11 sürümünde bölümü configuration'ın kökünde arıyor. Bölümü Logging altında tutmak istiyorsan method'a builder.Configuration.GetSection("Logging") ver. Configuration hatası sessiz olduğu için, sampling'i açtıktan sonra mutlaka bir kez saymanı öneririm.

Trace-Based Sampling

Random sampling her log kaydı için ayrı zar atar. Bir isteğin BookViewed satırı yazılırken aynı isteğin Warning'i atılabilir; elinde yarım istekler kalır. Trace-based sampler kararı log kaydına değil, o anki Activity'ye bırakır: trace kaydediliyorsa (Activity.Recorded) isteğin bütün log'ları yazılır, kaydedilmiyorsa hiçbiri. Böylece log ile trace aynı istekler için elinde olur.

Baştaki ilk sorunun cevabı burada. AddTraceBasedSampler() açıkken dört istek attım: biri W3C (World Wide Web Consortium) traceparent header'ında sampled bayrağı (-01) olan, biri bayrağı kapalı (-00) olan, ikisi de header'sız. Sonuncusu 503 dönen 100 numaralı kitap:

curl -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' http://localhost:17445/books/7
curl -H 'traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00' http://localhost:17445/books/8
curl http://localhost:17445/books/9
curl http://localhost:17445/books/100

Konsolda isteklerden kalan tek satır:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed

Uygulamanın kendi başlangıç log'ları (Microsoft.Hosting.Lifetime) yazıldı, çünkü onlar bir Activity içinde değil. Ama header'sız gelen istekler için ASP.NET Core bir Activity oluşturuyor; tracing kurulu olmadığı için onu kimse "kaydedilecek" diye işaretlemiyor ve sampler o isteğin bütün log'larını atıyor. 100 numaralı kitabın Error satırı da gitti. Yani tahminin "evet, hata her zaman yazılır" idiyse gerçek cevap hayır. Trace-based sampling'i yalnız OpenTelemetry tracing'i ve onun sampler'ı kuruluyken aç; kurulumun ayrıntısı ilerideki DevOps › Observability serisinde, traceparent'ın kendisi serinin "Correlation ID ve Trace Context" yazısında.

Buffering: Hata Olunca Geçmişi Yazmak

Sampling'in temel sorunu kör olması: hangi isteğin ilginç olacağını önceden bilemez. Oysa senin en çok ihtiyaç duyduğun Debug satırları tam olarak hata alan isteğin satırlarıdır. Buffering bu ikilemi çözüyor: log'ları bellekte tut, istek başarılı biterse at, hata olursa yaz. Buffering aynı ailenin 9.5 sürümüyle geldi; ASP.NET Core'a özel, istek başına çalışan hâli Microsoft.AspNetCore.Diagnostics.Middleware paketinde.

Kurallar appsettings.Buffer.json'da:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Bookstore.Catalog": "Debug",
      "Microsoft.AspNetCore": "Warning"
    },
    "PerIncomingRequestLogBuffering": {
      "AutoFlushDuration": "00:00:00",
      "Rules": [
        {
          "CategoryName": "Bookstore.Catalog",
          "LogLevel": "Debug"
        }
      ]
    }
  }
}

İki ayrıntı önemli. Birincisi, Bookstore.Catalog için filtre seviyesini Debug'a indirdim: buffering filtreden sonra çalışır, filtrenin attığı kaydı buffer'a koyamazsın. İkincisi, kural Debug ve altını buffer'a alıyor; Information ve üstü her zamanki gibi anında yazılıyor. Endpoint hata yakaladığında buffer'ı flush ediyor:

app.MapGet("/books/{id:int}", (int id, BookService books, ILogger<Program> logger, IServiceProvider services) =>
{
    using IDisposable? scope = logger.BeginScope("Catalog request from {Channel}", "web");
    try
    {
        return Results.Ok(books.GetBook(id));
    }
    catch (TimeoutException ex)
    {
        Log.BookLoadFailed(logger, ex, id);
        // hata oldu: bu isteğin buffer'daki Debug log'larını şimdi yaz
        services.GetService<PerRequestLogBuffer>()?.Flush();
        return Results.Problem(statusCode: 503);
    }
});

PerRequestLogBuffer'ı GetService ile alıyorum, çünkü demo uygulamada buffer yalnız buffer modunda kayıtlı; normal bir projede onu doğrudan parametre olarak inject edersin. Başarılı 7 numaralı kitap ve başarısız 100 numaralı kitap için konsol:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed
fail: Program[2005]
      Failed to load book 100
      System.TimeoutException: Database query for book 100 timed out
         at Bookstore.Catalog.BookService.GetBook(Int32 id) in /src/Bookstore.Catalog/BookService.cs:line 13
         at Program.<>c.<<Main>$>b__0_0(Int32 id, BookService books, ILogger`1 logger, IServiceProvider services) in /src/Bookstore.Catalog/Program.cs:line 27
dbug: Bookstore.Catalog.BookService[2001]
      Cache lookup for book 100
dbug: Bookstore.Catalog.BookService[2002]
      Cache miss for book 100, loading from database

Başarılı isteğin iki Debug satırı istek bitince buffer'la birlikte atıldı. Başarısız isteğinkiler ise Error'dan sonra yazıldı. Sıraya dikkat: buffer'daki kayıtlar flush anında yazılır, dokümantasyon da sıranın korunmadığını, yalnız orijinal zaman damgasının korunduğunu söylüyor. Bir sonraki bölümde o zaman damgasının da sürprizi olduğunu göreceğiz.

HTTP isteği olmayan yerler için, örneğin bir BackgroundService için, aynı paketin global hâli var: AddGlobalBuffer ile kaydedip GlobalLogBuffer'ı inject eder ve hata anında Flush() çağırırsın. Global buffer bir ring buffer: MaxBufferSizeInBytes dolunca en eski kayıtlar sessizce düşer. Per-request buffer'ı flush etmek global buffer'ı da flush eder; istek dışındaki bir log per-request kuralına uysa bile global buffer'a gider.

Seviyeyi Restart'sız Değiştirmek

Production'da bir sorunu incelerken tek bir category için Debug'ı on dakikalığına açmak istersin; bunun için deploy ya da restart gerekmemeli. Microsoft.Extensions.Logging, appsettings.json değişikliklerini varsayılan olarak izliyor (reloadOnChange). Uygulama çalışırken 7 numaralı kitabı istedim, ardından dosyaya "Bookstore.Catalog": "Debug" satırını ekleyip 8 numaralıyı istedim:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed
dbug: Bookstore.Catalog.BookService[2001]
      Cache lookup for book 8
dbug: Bookstore.Catalog.BookService[2002]
      Cache miss for book 8, loading from database
info: Bookstore.Catalog.BookService[2003]
      Book 8 viewed

Sampling ve buffering kuralları da IOptionsMonitor<T> üzerinden okunuyor, yani aynı şekilde canlı değişiyor. Kuralı Probability: 1 ile başlattım, 500 istek attım, dosyada değeri 0.1 yapıp 500 istek daha attım:

phase1 viewed=495
phase2 viewed=45

İlk 500 istekte 495 BookViewed (beş istek hata aldı), ikinci 500'de 45. Burada dosyayı elle düzenledim; gerçek hayatta değer Azure App Configuration gibi reload destekleyen bir configuration provider'dan gelir. Container'da dosyayı değiştirmek çoğu zaman pratik değildir, bunu unutma.

Serilog kullanıyorsan aynı işi LoggingLevelSwitch yapıyor. Switch'i singleton olarak kaydedip bir admin endpoint'inden değiştiriyorum:

LoggingLevelSwitch levelSwitch = new(LogEventLevel.Information);
builder.Services.AddSingleton(levelSwitch);
builder.Services.AddSerilog(lc => lc
    .MinimumLevel.ControlledBy(levelSwitch)
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .WriteTo.Console());

// gerçek projede bu endpoint mutlaka authorization arkasında olmalı
app.MapPut("/admin/log-level/{level}", (LogEventLevel level, LoggingLevelSwitch sw, ILogger<Program> logger) =>
{
    LogEventLevel previous = sw.MinimumLevel;
    sw.MinimumLevel = level;
    logger.LogWarning("Minimum log level changed from {PreviousLevel} to {NewLevel}", previous, level);
    return Results.Ok(new { previous, current = level });
});

Önce 7, sonra switch'i Debug'a alıp 8, sonra geri Information'a alıp 9 numaralı kitap:

[05:06:40 INF] Book 7 viewed
[05:06:40 WRN] Minimum log level changed from Information to Debug
[05:06:40 DBG] Cache lookup for book 8
[05:06:40 DBG] Cache miss for book 8, loading from database
[05:06:40 INF] Book 8 viewed
[05:06:40 WRN] Minimum log level changed from Debug to Information
[05:06:40 INF] Book 9 viewed

Seviye değişikliğinin kendisini Warning olarak logluyorum: "bu saatten sonra log hacmi neden üç katına çıktı?" sorusunun cevabı log'un içinde dursun. Endpoint'in yanıtı {"previous":2,"current":1}; enum'lar sayı olarak serialize ediliyor, kendi API'nde string'e çevirmek isteyebilirsin. Bu endpoint'i ASP.NET Core Web API serisinin "Authorization: Roller, Policy'ler ve Resource-Based Yetkilendirme" yazısındaki gibi bir policy arkasına koymadan production'a çıkarma; log seviyesini değiştirebilen biri log hacmini, yani faturanı da değiştirebilir.

Üretimde Dikkat

Hacmi seviye ve EventId bazında düzenli ölç. Yukarıdaki sayma script'inin aynısını log aracının sorgu dilinde yazmak beş dakikalık iş; serinin "Seq ile Structured Log'ları Okumak" yazısında group by ile bunu yapıyoruz. Hangi event'in faturanın yarısını oluşturduğunu bilmeden sampling oranı seçmek tahminden ibaret.

Microsoft'un sampling rehberi seviyeye göre açık bir tavsiye veriyor: Information'a sampling uygula, Warning için düşün, Error ve Critical'a hiç uygulama, Debug ve Trace zaten production'da kapalı olmalı. Kurallarına her zaman LogLevel ve mümkünse CategoryName yaz.

Buffering bedava değil: kayıtlar flush edilene kadar process belleğinde duruyor. Varsayılan sınırlara güvenme, MaxBufferSizeInBytes ve MaxLogRecordSizeInBytes değerlerini yük testinde ölçerek belirle. AutoFlushDuration ise flush'tan sonra buffering'in ne kadar süre askıya alınacağını, yani bütün log'ların anında yazılacağını belirliyor. Ben demo için sıfır yaptım; hata kümelenmesi yaşanan bir sistemde birkaç saniyelik bir değer, hatanın hemen arkasından gelen log'ları da görmeni sağlar.

Canlı seviye değişikliğinin bir bitiş zamanı olsun. "Debug'ı açtım, sonra kapatırım" demek, üç hafta sonra faturada fark edilen bir Debug demek. Admin endpoint'ine bir süre parametresi ekleyip süre dolunca switch'i eski değerine çeken küçük bir timer bu riski ortadan kaldırır.

Sık Düşülen Tuzaklar

Birincisi, Debug'ı production'da kalıcı açık unutmak. Tabloda gördüğün gibi aynı trafik 25 kat hacim üretiyor ve bunun çoğu kimsenin okumayacağı framework satırları.

İkincisi, sampling kuralını fazla geniş yazmak. Baştaki ikinci soru buydu: "Rules": [{ "Probability": 0.1 }] ile 1000 istek attım.

Information     111 lines     28281 bytes
Error             4 lines      2627 bytes
Total           115 lines     30908 bytes

10 Error'dan 4'ü, 10 Warning'den hiçbiri kaldı. Seviyesiz bir kural bütün seviyeleri kapsar. Hata oranı alarmın artık gerçek oranın onda birini görüyor ve bunu kimse fark etmiyor, çünkü sayılar "makul" görünüyor.

Üçüncüsü, buffer'dan gelen kayıtların canlı kayıtlarla aynı olduğunu sanmak. Buffering örneğini JSON formatter, IncludeScopes ve zaman damgasıyla tekrar çalıştırdım. Gerçek satırlar (ilk satırdaki stack trace'i ... ile kısalttım):

{"Timestamp":"05:05:39.797 ","EventId":2005,"LogLevel":"Error","Category":"Program","Message":"Failed to load book 100","Exception":"...","State":{"Message":"Microsoft.Extensions.Logging.ExtendedLogger+ModernTagJoiner","exception.type":"System.TimeoutException","BookId":100,"{OriginalFormat}":"Failed to load book {BookId}"},"Scopes":[{"Message":"SpanId:6b0f467e2ea05d1c, TraceId:a9d712d8bcf4c9352b882554c9618821, ParentId:0000000000000000","SpanId":"6b0f467e2ea05d1c","TraceId":"a9d712d8bcf4c9352b882554c9618821","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HNPT7J4NSF9J","ConnectionId":"0HNPT7J4NSF9J"},{"Message":"RequestPath:/books/100 RequestId:0HNPT7J4NSF9J:00000001","RequestId":"0HNPT7J4NSF9J:00000001","RequestPath":"/books/100"},{"Message":"Catalog request from web","Channel":"web","{OriginalFormat}":"Catalog request from {Channel}"}]}
{"Timestamp":"02:05:39.796 ","EventId":2001,"LogLevel":"Debug","Category":"Bookstore.Catalog.BookService","Message":"Cache lookup for book 100","Exception":"","State":{"Message":null,"BookId":"100","{OriginalFormat}":"Cache lookup for book {BookId}"}}
{"Timestamp":"02:05:39.797 ","EventId":2002,"LogLevel":"Debug","Category":"Bookstore.Catalog.BookService","Message":"Cache miss for book 100, loading from database","Exception":"","State":{"Message":null,"BookId":"100","{OriginalFormat}":"Cache miss for book {BookId}, loading from database"}}

Canlı yazılan Error satırında dört scope var: TraceId, SpanId, RequestPath ve bizim Channel'ımız. Buffer'dan gelen iki Debug satırında hiç Scopes yok. Dokümantasyon bunu açıkça yazıyor: buffering scope'ları desteklemiyor ve flush edilen kayıtlarda ActivityTraceId, ActivitySpanId hep boş. Pratikte bu şu demek: log aracında "bu TraceId'nin bütün log'ları" sorgusu, tam da görmek istediğin Debug satırlarını getirmez. Bağlamın kaybolmasını istemiyorsan TraceId ya da OrderId'yi scope'a değil, event'in kendi parametresine koy.

Aynı çıktıda iki sürpriz daha var. Zaman damgaları: canlı satır yerel saatle 05:05:39.797, buffer'dan gelenler 02:05:39.796; makine UTC (Coordinated Universal Time) +3 saat diliminde olduğu için tam üç saat geride, yani UTC yazılmış. Console formatter'ında UseUtcTimestamp kapalıyken bile böyle. İkincisi, BookId canlı satırda sayı (100), buffer'dan gelende string ("100"): kayıtlar buffer'a girerken serialize ediliyor. Log aracında BookId > 50 gibi sayısal bir sorgu bu satırları kaçırabilir.

Dördüncüsü, filtre ile buffer'ı karıştırmak. Default seviyesi Information'ken Debug için buffer kuralı yazarsan buffer hep boş kalır, çünkü kayıt buffer'a ulaşmadan filtrede elenir. Flush ettiğin hâlde Debug satırı göremiyorsan önce filtre seviyesine bak.

Küçük Bir Deneme

★☆☆ Örnek uygulamayı --Logging:LogLevel:Microsoft.AspNetCore=Information ile başlat ve 100 istek at. Framework'ten gelen satırların toplam baytın yüzde kaçı olduğunu hesapla.

★★☆ Sampling kuralını iki kurala böl: Bookstore.Catalog category'sinin Information seviyesine 0.1, geri kalan her şeye 1.0. 1000 istekle bütün Warning ve Error satırlarının kaldığını doğrula. Kural sırasını değiştirince sonuç değişiyor mu?

★★★ Buffering örneğinde BookService'teki Debug event'lerine bir traceId parametresi ekle (Activity.Current?.TraceId.ToString()). Flush edilen satırlarda trace bilgisinin artık durduğunu JSON çıktısında göster ve bunun log satırı başına kaç bayt eklediğini ölç.

Bu yazıyla Blok A'yı, yani .NET 10 üzerindeki kemik yapıyı bitirdik. Son yazıda geriye bakacağız: .NET 8'den .NET 11'e logging tarafında neler geldi, enrichment, redaction, FakeLogger, buffering ve generic LoggerMessage hangi sürümde eklendi ve eski bir projede Serilog 2/3 tarzı Startup yapılandırmasıyla karşılaştığında onu nasıl okursun.