Log'lardan Sebep Bulmak: Correlation ID, Trace ID ve Zaman Çizelgesi Kurmak

Sürüm notu: Bu yazıdaki kodlar .NET 10 ile derlenip denenmiştir; log sorguları jq 1.7.1 ile çalıştırılmıştır.

Önce Tahmin Et

Bookstore'da ödeme hataları başladı. Elinde iki servisin log'u (sipariş ve ödeme) ve bir değişiklik kaydı var. Kayıtta 09:25:47'de ödeme servisinde bir configuration değişikliği, 09:26:17'de ödeme servisinin 2.4.0'dan 2.4.1'e deploy'u görünüyor. Log'larda en çok tekrar eden hata satırı 245 kez yazılmış "An unhandled exception has occurred while executing the request." mesajı. Üç soru: Hatayı deploy mu başlattı, configuration değişikliği mi? En çok tekrar eden mesaj kök sebebe mi işaret ediyor? Ve deploy'un hiç mi suçu yok? Cevaplar, iki servisi gerçekten çalıştırıp ürettiğim log'larda.

Log'a Bakmadan Önce Soruyu Daralt

Production'da log aramak, kütüphanede kitap aramaya benzer: ne aradığını bilmiyorsan raflar arasında kaybolursun. Arama kutusuna bir şey yazmadan önce üç sorunun cevabını netleştir. Ne bozuk: hangi endpoint, hangi hata, kullanıcı ne görüyor? Ne zamandan beri: ilk şikâyetin saati, ilk hatanın saati? Kimi etkiliyor: herkesi mi, bir müşteri grubunu mu, tek bir pod'u mu?

Bu yazının vakasında cevaplar şöyle: checkout endpoint'i 500 dönüyor, 09:25 civarında başlamış, rastgele siparişleri etkiliyor. Elimizdeki kanıt structured log ve bir değişiklik kaydı. Log'u nasıl ürettiğimiz (ILogger, Serilog, structured logging) Web API (Application Programming Interface) serisinin "ASP.NET Core'da Logging: ILogger, Log Seviyeleri, Structured Logging ve Serilog" yazısında ve ilerideki .NET'te Logging serisinde; log altyapısı (toplama, saklama) ilerideki Observability serisinde. Burada log'u okuyoruz.

Structured Log'un Anatomisi

İki servis de JSON (JavaScript Object Notation) console formatter'ıyla yazıyor ve scope'ları açık:

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.ClearProviders();
builder.Logging.AddJsonConsole(options =>
{
    options.IncludeScopes = true;
    options.UseUtcTimestamp = true;
    options.TimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffZ";
});
builder.Services.AddProblemDetails();
builder.Services.AddHttpClient("payments", client =>
    client.BaseAddress = new Uri(builder.Configuration["Payments:BaseUrl"]!));

WebApplication app = builder.Build();
app.UseExceptionHandler();

app.MapPost("/orders/{id:int}/checkout", async (int id, IHttpClientFactory factory, ILogger<Program> logger) =>
{
    // OrderId bu request'teki her log satırına scope olarak eklenir
    using IDisposable? scope = logger.BeginScope(new Dictionary<string, object> { ["OrderId"] = id });
    string customerEmail = $"customer{id}@example.com";
    logger.LogInformation("Checkout started for order {OrderId} by {CustomerEmail}", id, customerEmail);

    HttpClient payments = factory.CreateClient("payments");
    using HttpResponseMessage response = await payments.PostAsync($"/payments/{id}", null);
    if (!response.IsSuccessStatusCode)
    {
        logger.LogError("Payment failed for order {OrderId} with status {StatusCode}", id, (int)response.StatusCode);
        throw new InvalidOperationException($"Payment failed for order {id}");
    }

    logger.LogInformation("Checkout completed for order {OrderId}", id);
    return Results.Ok(new { id, status = "Paid" });
});

app.Run();

Ödeme servisi bir kart sağlayıcısını taklit ediyor: her çağrı 80 ile 260 ms arasında sürüyor, configuration'daki Provider:TimeoutMs aşılırsa 504 dönüyor. Değer her istekte IOptionsMonitor<ProviderOptions>.CurrentValue ile okunuyor; yani dosya değişince restart gerekmeden yeni değer geçerli oluyor. Bunu aklında tut.

Sipariş servisinin yazdığı bir hata satırı:

{
  "Timestamp": "2026-11-08T09:25:48.418Z",
  "EventId": 0,
  "LogLevel": "Error",
  "Category": "Program",
  "Message": "Payment failed for order 1211 with status 504",
  "State": {
    "OrderId": 1211,
    "StatusCode": 504,
    "{OriginalFormat}": "Payment failed for order {OrderId} with status {StatusCode}"
  },
  "Scopes": [
    {
      "Message": "SpanId:dfe81cce851872b8, TraceId:7d861d9c26dcdd37d55db88d26e3e1d7, ParentId:0000000000000000",
      "SpanId": "dfe81cce851872b8",
      "TraceId": "7d861d9c26dcdd37d55db88d26e3e1d7",
      "ParentId": "0000000000000000"
    },
    {
      "Message": "ConnectionId:0HNPTF8OHRA7J",
      "ConnectionId": "0HNPTF8OHRA7J"
    },
    {
      "Message": "RequestPath:/orders/1211/checkout RequestId:0HNPTF8OHRA7J:00000001",
      "RequestId": "0HNPTF8OHRA7J:00000001",
      "RequestPath": "/orders/1211/checkout"
    },
    {
      "Message": "System.Collections.Generic.Dictionary`2[System.String,System.Object]",
      "OrderId": 1211
    }
  ]
}

Bu satırda üç farklı kimlik var ve hepsinin işi ayrı. TraceId, bu request'in dağıtık iz kimliği; servis sınırını geçer. RequestId ve ConnectionId, Kestrel'in yerel kimlikleri; yalnızca bu process'te anlamlı. OrderId ise iş tarafının correlation ID'si: destek ekibi "1211 numaralı sipariş" diye geldiğinde aradığın şey. Kendi koduma bir şey eklemeden TraceId, SpanId ve ParentId'nin scope'ta bulunması, ASP.NET Core host'unun varsayılan activity tracking ayarı sayesinde; ben yalnızca IncludeScopes açtım. State içindeki alanlar da mesajın parçası değil, ayrı alanlar; yani StatusCode = 504 diye sorgulanabilir.

W3C traceparent ile Request'i Servisler Arasında İzlemek

TraceId'nin servis sınırını nasıl geçtiğini görmek için sipariş servisine elle bir traceparent header'ı gönderdim. W3C (World Wide Web Consortium) Trace Context standardına göre bu header'ın biçimi version-traceid-parentid-flags: 2 hex sürüm, 32 hex trace ID, 16 hex parent span ID ve 2 hex flag.

curl -s -X POST -H "traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" \
  http://localhost:5485/orders/3001/checkout

jq -c 'select(.Scopes[0].TraceId? == "4bf92f3577b34da6a3ce929d0e0e4736")
  | {svc: (input_filename|sub(".log";"")), msg: .Message, span: .Scopes[0].SpanId, parent: .Scopes[0].ParentId}' \
  orders.log payments.log

{"svc":"orders","msg":"Checkout started for order 3001 by customer3001@example.com","span":"eff40b740adb25bb","parent":"00f067aa0ba902b7"}
{"svc":"orders","msg":"Checkout completed for order 3001","span":"eff40b740adb25bb","parent":"00f067aa0ba902b7"}
{"svc":"payments","msg":"Payment authorized for order 3001 in 247 ms","span":"8af86f601507cbe2","parent":"920d797f4233866b"}

Üç ayrıntı okunmaya değer. Sipariş servisi gelen trace ID'yi aynen benimsedi, kendi span'i için yeni bir ID üretti ve parent olarak header'daki span'i yazdı. Ödeme servisinde trace ID aynı, ama parent 920d797f4233866b: bu ne sipariş servisinin server span'i ne de benim header'ım. HttpClient'ın giden çağrı için açtığı client span'i bu. O span sipariş servisinin log'unda görünmüyor, çünkü System.Net.Http.HttpClient kategorisini Warning'e çektim. Bağlantıyı kurmak için hiç kod yazmadım: HttpClient header'ı ekledi, ASP.NET Core karşı tarafta okudu.

Müşterinin Elindeki traceId'den Log'a

Kullanıcının gördüğü hata yanıtı log'a giden en kısa yoldur. AddProblemDetails ile 500 yanıtında traceId geliyor (mekaniği Web API serisinin "ASP.NET Core'da Global Hata Yönetimi: Exception Middleware ve ProblemDetails" yazısında; header'ların bir kısmını kestim):

HTTP/1.1 500 Internal Server Error
Content-Type: application/problem+json

{"type":"https://tools.ietf.org/html/rfc9110#section-15.6.1","title":"An error occurred while processing your request.","status":500,"traceId":"00-9f370a6bb2a4cecf88a0a618ff4163e3-08b74be4487177d3-00"}

Dikkat: buradaki traceId, log'daki TraceId alanıyla aynı string değil. Tam bir traceparent değeri; log'da aranacak kısım ortadaki 32 karakter. Sondaki 00 flag'i "sampled değil" demek; log'larda trace ID yine de yazılıyor. Ortadaki kısımla iki servisi birden sorgulayınca:

{"svc":"orders","t":"09:39:29.583","lvl":"Information","msg":"Checkout started for order 2001 by customer2001@example.com"}
{"svc":"orders","t":"09:39:29.796","lvl":"Error","msg":"Payment failed for order 2001 with status 504"}
{"svc":"orders","t":"09:39:29.812","lvl":"Error","msg":"An unhandled exception has occurred while executing the request."}
{"svc":"payments","t":"09:39:29.779","lvl":"Warning","msg":"Card provider timed out after 150 ms for order 2001"}

Sipariş servisindeki iki Error satırının sebebi, 17 ms önce ödeme servisinde yazılmış bir Warning: kart sağlayıcısı 150 ms'de timeout. Tek bir request için cevap bu kadar net.

Zaman Çizelgesi: İlk Hata ve En Çok Hata

Tek request'in hikâyesi "neden"i söyler ama "neden şimdi"yi söylemez. Bunun için olayları aynı eksene koymak gerekiyor. İki servisi başlattım, saniyede yaklaşık 6 checkout gönderen bir trafik verdim ve senaryoyu oynattım: 35 saniye sonra ödeme servisinin appsettings.json'ındaki Provider:TimeoutMs değerini 2000'den 150'ye çektim, 30 saniye sonra servisi 2.4.1 olarak yeniden başlattım (deploy), 15 saniye sonra log seviyesini Debug'a aldım. Değişiklik kaydı:

2026-11-08T09:25:47 config-change payments Provider:TimeoutMs 2000->150 (by ops-portal)
2026-11-08T09:26:17 deploy payments 2.4.0->2.4.1 (pipeline #812)
2026-11-08T09:26:33 log-level payments Default Information->Debug (diagnosis)

Önce en çok tekrar eden hatalar. Mesajlardaki sayıları N'ye çevirip grupluyorum, yoksa her sipariş numarası ayrı bir mesaj sayılır:

jq -r 'select(.LogLevel=="Error" or .LogLevel=="Warning")
  | (input_filename|sub(".log";"")) + "  " + (.Message|gsub("[0-9]+";"N"))' orders.log payments.log \
  | sort | uniq -c | sort -rn

 245 orders  An unhandled exception has occurred while executing the request.
 244 payments  Card provider timed out after N ms for order N
 244 orders  Payment failed for order N with status N

Listenin tepesinde, hiçbir şey söylemeyen genel bir mesaj var: exception handler middleware'in her unhandled exception'da yazdığı satır. En çok hata, genellikle zincirin en sonundaki, en gürültülü halkadır. Şimdi her servis ve seviye için ilk satır:

jq -r 'select(.LogLevel=="Error" or .LogLevel=="Warning")
  | [.Timestamp, (input_filename|sub(".log";"")), .LogLevel, .Message] | @tsv' orders.log payments.log \
  | sort | awk -F'\t' '!seen[$2 FS $3]++'

2026-11-08T09:25:48.407Z	payments	Warning	Card provider timed out after 150 ms for order 1211
2026-11-08T09:25:48.418Z	orders	Error	Payment failed for order 1211 with status 504

İlk sinyal ödeme servisinden, configuration değişikliğinden bir saniye sonra geliyor. 10 saniyelik dilimlerde hata sayısı da aynı şeyi söylüyor:

jq -r 'select(.LogLevel=="Error" and .Category=="Program") | .Timestamp[11:18] + "0"' orders.log | sort | uniq -c

   1 09:25:40
  37 09:25:50
  40 09:26:00
  38 09:26:10
  34 09:26:20
  39 09:26:30
  43 09:26:40
  12 09:26:50

Aynı dilimlerde başlayan checkout sayısı 59 ile 67 arasında sabit; trafik artışı yok. Hepsini tek tabloda birleştiriyorum; saatler UTC (Coordinated Universal Time):

İki servis de UTC yazdığı için satırlar doğrudan sıralanabiliyor. Baştaki soruların cevabı tabloda. Hatalar deploy'dan 30 saniye önce başlamış; deploy'u geri almak hiçbir şeyi düzeltmezdi. Sebep configuration değişikliği. Ama deploy'un da kendi izi var: 245 ile 244 arasındaki fark, servis yeniden başlarken 09:26:18.193'te düşen tek bir Connection refused. İki ayrı sorun aynı belirtiyi (500) veriyor; biri sürekli, biri anlık.

Bir ayrıntı daha: configuration değişikliği log'larda hiç görünmüyor. IOptionsMonitor yeni değeri sessizce aldı. Değişiklik kaydı olmasaydı, zaman çizelgesindeki en önemli satır eksik kalırdı. Değişiklikleri (deploy, config, feature flag) log'larla aynı yerde tutmak bu yüzden önemli.

Log Seviyesini Runtime'da Açmak

WebApplication.CreateBuilder, appsettings.json'u dosya değişikliklerini izleyerek yükler ve logging filtreleri configuration'a bağlıdır. Yani Logging:LogLevel değerini dosyada değiştirince process yeniden başlamadan yeni seviye geçerli olur. Senaryoda 09:26:33'te ödeme servisinde Default'u Debug'a çektim; ilk Debug satırı aynı saniyenin içinde geldi:

{"t":"09:26:33.991","msg":"Calling card provider for order 1507, timeout 150 ms"}

Bu satır, teşhisi kanıta çeviriyor: servis 150 ms timeout ile çalışıyor. Production'da bunu yaparken üç kural koyarım. Seviyeyi yalnızca ilgili kategori için aç (Default değil, Bookstore.Payments gibi); Debug'da 127 satır yazan bu küçük servis, gerçek trafikte saniyede binlerce satır yazar. Açtığın seviyeyi bir süre sonra geri al ve bunu değişiklik kaydına yaz. Kubernetes'te configuration'ı ConfigMap'ten dosya olarak mount ediyorsan, Kubernetes dokümanına göre subPath ile mount edilen ConfigMap güncelleme almaz; o durumda dosya hiç değişmez ve reload olmaz.

Log hiç yoksa ya da tam ihtiyacın olan yerde susuyorsa ne yaparsın? Önce metrik: hata oranı, latency, thread pool. Sonra process'in kendisi: 09'daki dump ve 10'daki dotnet-stack ve dotnet-trace, log'un yazmadığı şeyi gösterir. En son çare, eksik log'u ekleyip deploy etmek; ama o deploy da zaman çizelgesine bir satır olarak girer.

Aynı Sorgular Seq, Kibana ve KQL'de

Ben jq ile düz dosyalar üzerinde çalıştım; production'da bu log'lar bir log platformunda durur. Aşağıdaki sorgu sözdizimlerini ilgili ürünlerin dokümanından aldım, bu yazı için çalıştırmadım:

Seq:
@TraceId = '7d861d9c26dcdd37d55db88d26e3e1d7'

Kibana (KQL, ECS):
trace.id : "7d861d9c26dcdd37d55db88d26e3e1d7"

Application Insights (KQL):
union requests, dependencies, traces, exceptions
| where operation_Id == "7d861d9c26dcdd37d55db88d26e3e1d7"
| order by timestamp asc

Kibana'daki KQL (Kibana Query Language) sorgusu, log'ların ECS (Elastic Common Schema) alan adlarıyla index'lendiğini varsayıyor; Application Insights'taki KQL (Kusto Query Language) ise W3C trace ID'sini operation_Id alanında tutuyor. Yani iki farklı "KQL" var ve birbirine benzemiyor; ekip içinde "KQL'de ararız" derken hangisini kastettiğini netleştir. Hangi platformu kullanırsan kullan yöntem aynı: önce en gürültülü mesajı değil ilk sinyali bul, sonra trace ID ile tek bir request'in hikâyesini oku, en son olayları değişiklik kaydıyla aynı eksene koy.

Üretimde Dikkat

Log'lar kişisel veri taşır ve debugging sırasında en çok kopyalanıp yapıştırılan şey de log'dur. Bu vakada checkout satırı müşterinin e-postasını içeriyor:

grep -cE '[A-Za-z0-9._%+-]+@example\.com' orders.log

635

Log'u ticket'a, chat'e ya da bir AI (Artificial Intelligence, yapay zekâ) aracına yapıştırmadan önce maskele. jq ile bütün string alanlarda e-postayı değiştirmek tek satır:

jq -c 'select(.Message|startswith("Checkout started"))
  | walk(if type == "string" then gsub("[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+"; "[redacted-email]") else . end)
  | {Message, State}' orders.log | head -1

{"Message":"Checkout started for order 1001 by [redacted-email]","State":{"OrderId":1001,"CustomerEmail":"[redacted-email]","{OriginalFormat}":"Checkout started for order {OrderId} by {CustomerEmail}"}}

walk önemli: e-posta hem render edilmiş Message'da hem de State içindeki ayrı alanda duruyor; yalnızca birini maskelemek yetmez. Asıl düzeltme log'a hiç PII (Personally Identifiable Information, kişisel veri) yazmamak; e-posta yerine müşteri ID'si yeterli. Bunun yapılışı .NET'te Logging serisinin konusu. Debugging tarafındaki kural: log'larda secret ya da kişisel veri aramaya çıkıyorsan (örneğin "token sızmış mı" diye), bulduğunu paylaşma, varlığını raporla ve secret'ı döndür. Log platformundaki erişim yetkilerini de "herkes her şeyi görsün" değil, ihtiyaca göre ver.

Sık Düşülen Tuzaklar

En çok tekrar eden hatayla başlamak. Bu vakada en sık mesaj, hiçbir şey anlatmayan genel exception handler satırıydı. İlk sinyal başka servisteki bir Warning'di; Warning'leri filtreleyip yalnızca Error'a bakan biri onu hiç görmezdi.

"Deploy'dan sonra başladı" demeden önce saatlere bakmamak. Hatalar deploy'dan 30 saniye önce başlamıştı. Zaman çizelgesi kurmadan rollback yapsaydık, bir şey değişmeyecek, ekip yanlış izi sürecekti.

ProblemDetails'teki traceId'yi olduğu gibi aramak. O değer 00-...-...-00 biçiminde tam bir traceparent; log'daki TraceId alanı yalnızca ortadaki 32 karakter.

Farklı saat dilimlerinde yazan servisleri yan yana koymak. Bir servis yerel saatle, diğeri UTC ile yazıyorsa zaman çizelgesi 3 saat kayar ve sebep ile sonuç yer değiştirir. Her şeyi UTC yaz, ekranda çevir.

Configuration değişikliklerini kayıt altına almamak. IOptionsMonitor ile canlı değişen bir ayar log'da iz bırakmaz; değişiklik kaydı yoksa kök sebep görünmez kalır.

Küçük Bir Deneme

★☆☆ Bu yazıdaki "ilk hata" sorgusunu, Warning'leri dışarıda bırakıp yalnızca Error'larla çalıştır. Çıkan ilk satır seni hangi servise götürüyor?

★★☆ Ödeme servisine, IOptionsMonitor<ProviderOptions>.OnChange ile configuration değiştiğinde eski ve yeni TimeoutMs değerini yazan bir log satırı ekle. Senaryoyu tekrar oynat ve zaman çizelgesini yalnızca log'lardan, değişiklik kaydına bakmadan kur.

★★★ Sipariş servisine bir de stok servisi çağrısı ekle ve üç servisli bir zincir kur. Tek bir trace ID için bütün span'leri parent ilişkisiyle bir ağaç olarak basan bir jq ya da C# script'i yaz.

Log'lar bize "ne zaman ve hangi request'te" sorusunu cevapladı. Ama process çöktüyse, son log satırı hiçbir şey söylemiyorsa ya da bellek sessizce büyüyorsa, process'in o anki iç durumuna bakmak gerekir. Sonraki yazıda dotnet-dump ile crash ve memory dump analizine geçiyoruz.