Distributed Tracing ve Observability: Bir Siparişi Angular'dan RabbitMQ'ya Kadar İzlemek

Sürüm notu: Bu yazıdaki kodlar .NET 10, Aspire 13.6, OpenTelemetry .NET 1.21 (OpenTelemetry.Instrumentation.GrpcNetClient 1.21.0-beta.1), WolverineFx 6.64 ve dotnet-counters 10.0 ile derlenip denenmiştir; .NET 11 notundaki örnek .NET 11 SDK'sı (11.0.100) ile çalıştırıldı.

Önce Tahmin Et

02'den beri her service ServiceDefaults üzerinden OpenTelemetry'ye bağlı ve Aspire dashboard'unda bir "Traces" sayfası var. 11'de Ada'nın Emma siparişi BFF (Backend for Frontend; Angular'a özel ara backend), Ordering, RabbitMQ, Inventory, Payments ve Notifications'tan geçti. Dashboard'da o siparişin POST /api/orders trace'ini açtığında kaç service görürsün? İkinci soru: ödeme sonucu dışarıdaki ödeme sağlayıcısından webhook ile geliyor. Webhook'un span'ı siparişin trace'inde mi olur, ayrı bir trace mi açar? Cevaplar Aspire'ın telemetri export'undan.

ServiceDefaults'ta Eksik Olan Satırlar

İlk sorunun cevabı, 11'de bıraktığımız hâliyle: iki service. Aspire CLI'ın aspire export komutu dashboard'daki trace'leri OTLP (OpenTelemetry Protocol; telemetri verisini taşıyan standart protokol) JSON'u olarak bir zip'e yazıyor; parent span id'lerinden ağacı kuran küçük bir script ile sitedeki serilerin ortak örnek uygulaması Bookstore'un (bir online kitapçı) o siparişi şöyle görünüyordu (sütunlar: başlangıç ms, süre ms):

     0.0    111.4  [bff] POST /api/orders 202
     0.3    110.9    [bff] POST 202
     0.6    109.7      [ordering] POST /api/v{version:apiVersion}/orders/ 202
     2.4     20.7        [ordering] SELECT [CatalogBooks]
    27.7      7.4        [ordering] insert wolverine_outgoing_envelopes
    35.2      8.3        [ordering] insert wolverine.wolverine_incoming_envelopes
    47.3      2.0        [ordering] orderingdb
    49.4     52.2        [ordering] INSERT
   104.7      2.8        [ordering] delete
   108.1      1.7        [ordering] SELECT [o].[Status] [OrderItems]
10 spans; scopes: ['Microsoft.AspNetCore', 'OpenTelemetry.Instrumentation.SqlClient', 'System.Net.Http']

Trace, outbox tablosuna yazılan satırla bitiyor. Saga, stok, ödeme, bildirim: hiçbiri yok. HTTP ve SQL span'ları var, çünkü ServiceDefaults ASP.NET Core ve HttpClient instrumentation'ını açıyor, Aspire'ın Aspire.Microsoft.EntityFrameworkCore.SqlServer component'i de OpenTelemetry.Instrumentation.SqlClient'ı kendisi ekliyor. Redis için Aspire.StackExchange.Redis aynısını yapıyor. Eksik olan, mesajlaşma tarafı: Wolverine span'larını Wolverine adlı bir ActivitySource'tan üretiyor ve kimse onu dinlemiyordu. gRPC için de şablonun yorum satırında bıraktığı instrumentation var. ServiceDefaults'a eklenenler:

.WithMetrics(metrics =>
{
    metrics.AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddRuntimeInstrumentation()
        // Wolverine'in meter'ının adı "Wolverine:<uygulama adı>", bu yüzden wildcard gerekiyor
        .AddMeter("Wolverine*")
        // Business metric'ler: her service kendi Meter'ına "Bookstore.<Service>" adını veriyor (12. yazı)
        .AddMeter("Bookstore.*");
})
.WithTracing(tracing =>
{
    tracing.AddSource(builder.Environment.ApplicationName)
        .AddAspNetCoreInstrumentation(tracing =>
            // Health check isteklerini trace'e alma
            tracing.Filter = context =>
                !context.Request.Path.StartsWithSegments(HealthEndpointPath)
                && !context.Request.Path.StartsWithSegments(AlivenessEndpointPath)
        )
        // BFF'nin Inventory çağrılarında rpc.* attribute'ları (service, method, status code)
        .AddGrpcClientInstrumentation()
        .AddHttpClientInstrumentation()
        // Wolverine'in span'ları: mesajı göndermek, almak, handler'ı çalıştırmak. Trace context mesajın
        // header'larında taşınıyor; başka bir service'teki handler aynı trace'e devam ediyor.
        .AddSource("Wolverine");
});

OpenTelemetry.Instrumentation.GrpcNetClient'ın NuGet'te yalnız beta sürümü var (1.21.0-beta.1); Directory.Packages.props'ta bunu bir yorumla not ettik. Wolverine'in meter adı uygulama adını da içerdiği için AddMeter("Wolverine") hiçbir şey yakalamıyor; Wolverine dokümanı da wildcard'ı söylüyor. Ayrıntılı OpenTelemetry kurulumu ve backend tarafı Observability serisinde; burada yalnız Bookstore'da neyin eksik kaldığına bakıyoruz.

Trace Context Mesajın İçinde

HTTP'de trace context traceparent header'ında taşınıyor ve bunu HttpClient ile ASP.NET Core kendiliğinden yapıyor. Mesajlaşmada bu işi library yapmak zorunda. Wolverine'in RabbitMQ'ya gönderdiği bir OrderPlaced'ı test için bağladığımız bir queue'dan aldık ve property'lerine baktık:

type:            Bookstore.Contracts.Ordering.OrderPlaced
correlation_id:  84804c281ad12445895ace55edc19889
parent-id:       00-84804c281ad12445895ace55edc19889-a81bf76074da83ef-03

parent-id header'ı W3C (World Wide Web Consortium; web standartlarını yayınlayan kuruluş) Trace Context biçiminde (00-<trace id>-<span id>-<flags>) gönderen span'ı taşıyor; Wolverine'in consumer tarafı bu değerden yeni bir child span açıyor. AMQP (Advanced Message Queuing Protocol; RabbitMQ'nun konuştuğu protokol) mesajının correlation_id'si de trace id'nin kendisi. Header'ın adı traceparent değil, Wolverine'e özgü. Wolverine kullanmayan bir consumer (ör. başka bir dilde yazılmış bir service) trace'e katılmak istiyorsa bu adı bilmek zorunda.

Span'ların attribute'ları da OpenTelemetry'nin messaging semantic convention'ları ile birebir aynı değil. Wolverine messaging.system, messaging.destination ve messaging.message_id yazıyor; güncel convention'lar messaging.system.name, messaging.destination.name ve messaging.message.id diyor. Convention'ların bu kısmı hâlâ "Development" durumunda ve spesifikasyon, kararlı hâle gelene kadar mevcut instrumentation'ların varsayılan çıktılarını değiştirmemesini istiyor. Bir fark daha var: spesifikasyon producer ile consumer arasında varsayılan olarak span link'lerini öneriyor; Wolverine consumer span'ını doğrudan producer'ın child'ı yapıyor. Tek mesajlık akışlarda bu, bütün checkout'u tek bir ağaç olarak görmeyi sağlıyor; batch işleyen bir consumer'da tek parent yetmezdi.

Checkout Trace'ini Okumak

Ekleme sonrası aynı akış (sistem ısınmışken, ikinci sipariş) 81 span ve beş service. SQL span'larını gizleyince:

     0.0     15.3  [bff] POST /api/orders 202
     0.7     14.4      [ordering] POST /api/v{version:apiVersion}/orders/ 202
    11.4      1.9        [ordering] send
    12.3      0.2        [notifications] receive
    13.3      8.5        [ordering] Bookstore.Ordering.Checkout.StartCheckout
    29.6      8.5          [inventory] Bookstore.Contracts.Inventory.ReserveStock
    45.3     10.5            [ordering] Bookstore.Contracts.Inventory.StockReserved
    63.3      5.6              [payments] Bookstore.Contracts.Payments.AuthorizePayment
    64.7      0.9                [payments] POST 202
  1066.8     12.6  [payments] POST /webhooks/payment-provider 200
  1088.3     10.0    [ordering] Bookstore.Contracts.Payments.PaymentSucceeded
  1105.6      9.9      [inventory] Bookstore.Contracts.Inventory.CommitStock
  1122.7      9.4        [ordering] Bookstore.Contracts.Inventory.StockCommitted
  1130.6     16.6          [notifications] receive

Birkaç şey hemen okunuyor. Kullanıcının beklediği kısım (BFF'nin span'ı) 15 ms; geri kalanı arka planda. Her RabbitMQ geçişi, bir handler'ın send'i ile diğer service'teki handler'ın başlaması arasında 8–10 ms. Bir saniyelik boşluk bizim kodumuz değil: ödeme sağlayıcısı charge'ı kabul ediyor, sonucu yaklaşık bir saniye sonra webhook ile gönderiyor. "Checkout neden 1,15 saniye?" sorusunun cevabı tek bakışta: sağlayıcı.

İkinci sorunun cevabı: webhook aynı trace'te. Sahte ödeme sağlayıcısının OpenTelemetry'si yok, ama içindeki ASP.NET Core gelen traceparent'tan bir Activity oluşturuyor ve webhook'u gönderen HttpClient aynı context'i header'a geri yazıyor. Webhook span'ının parent'ı sağlayıcıda; o span dashboard'a hiç gelmediği için ağaçta kök gibi duruyor ama trace id aynı. Gerçek bir ödeme sağlayıcısı bizim trace context'imizi webhook'a taşımaz; orada trace bu noktada kopar ve iki trace'i sipariş id'si ile eşleştirmek gerekir.

gRPC tarafında da yeni bir şey gördük. Kitap sayfasının trace'inde BFF'nin GetStock span'ı 34 ms; içinde Keycloak'a giden 29 ms'lik bir POST .../protocol/openid-connect/token span'ı var ve Inventory'nin kendisi 3 ms:

bff Client bookstore.inventory.v1.InventoryService/GetStock 34 {'rpc.system.name': 'grpc', 'rpc.method': 'bookstore.inventory.v1.InventoryService/GetStock', 'server.address': '_grpc.inventory', 'rpc.response.status_code': 'OK'}
bff Client POST 29 {'url.full': 'http://localhost:8180/realms/bookstore/protocol/openid-connect/token', 'http.response.status_code': '200 OK'}
inventory Server POST /bookstore.inventory.v1.InventoryService/GetStock 3 {'grpc.method': '/bookstore.inventory.v1.InventoryService/GetStock', 'grpc.status_code': '0'}

10'da eklediğimiz call credentials, token'ı gRPC çağrısının içinde alıyor; yani 09'daki 500 ms'lik deadline token alma süresini de kapsıyor. 11'de sistem yeni açıldığında ilk kitap sayfasının DeadlineExceeded almasının nedeni tam olarak bu: soğuk bir Keycloak'tan ilk token, ilk HTTP/2 bağlantısı ve Inventory'nin ilk isteği aynı 500 ms'ye sığmadı. Log'larda bu ayrım görünmüyordu; trace'te tek satır.

Trace Koptuğunda: Reconciliation

08'deki reconciliation job'ı webhook'u gelmeyen ödemeleri sağlayıcıya soruyor. Sahte sağlayıcıda webhook'ları düşürüp bir sipariş verdik. Siparişin trace'i 44 span'da, AuthorizePayment'ta bitti. Sonrası ayrı bir trace oldu:

     0.0     14.7  [ordering] Bookstore.Contracts.Payments.PaymentSucceeded
    29.2     19.7    [inventory] Bookstore.Contracts.Inventory.CommitStock
    60.2     11.2      [ordering] Bookstore.Contracts.Inventory.StockCommitted
    71.1     31.6        [notifications] receive
29 spans; scopes: ['OpenTelemetry.Instrumentation.SqlClient', 'OpenTelemetry.Instrumentation.StackExchangeRedis', 'Wolverine']

Bu trace'in OrderConfirmed mesajında parent-id başka bir trace id taşıyordu (077f2fd4…) ve correlation_id artık bir trace id değil, rastgele bir GUID'di (128 bitlik, benzersiz olması beklenen bir kimlik). Job bir HTTP isteğinden ya da mesajdan değil, bir timer'dan başlıyor; elinde siparişin trace context'i yok. Bir veritabanı satırından devam eden her iş (reconciliation, zamanlanmış job, outbox'ı başka bir process'in boşaltması) bu sorunu yaşar. Çözümü context'i satırla birlikte saklamak: Payment kaydına ilk isteğin traceparent'ını yazıp job'ın açacağı span'a bir link olarak eklemek. Spesifikasyonun link önermesinin bir nedeni de bu.

Log'lar ve Business Metric'ler

ServiceDefaults log'ları da OpenTelemetry ile gönderiyor ve her log satırı o anki trace id'yi taşıyor. Bir checkout'un log'larını Aspire CLI ile trace id'den çektik: aspire otel logs --trace-id 37987620… beş service'ten 34 kayıt döndürdü; Entity Framework Core'un (EF Core) SQL log'larını çıkarınca kalanlar:

[notifications] Order 01a1dacd-36e8-7ba3-96ad-e5fac7c385b8 placed by f7afeb42-184d-43b6-b035-e9bdb6100d33: 249.90 TRY, 1 line(s)
[inventory]     Reserved 1 line(s) for order 01a1dacd-36e8-7ba3-96ad-e5fac7c385b8 until 2026-11-14T16:24:04.6929290Z
[payments]      Webhook evt_3d41445029c9479385ff175c0a004ca2: payment for order 01a1dacd-36e8-7ba3-96ad-e5fac7c385b8 is Succeeded
[inventory]     Reservation 01a1dacd-37d4-796b-831e-a6d14a3636fd for order 01a1dacd-36e8-7ba3-96ad-e5fac7c385b8 Committed
[notifications] E-mail confirmed for order 01a1dacd-36e8-7ba3-96ad-e5fac7c385b8 sent to ada@example.com

Beş ayrı process'in log'unu sipariş id'si ile grep'lemek yerine tek sorgu. Logging serisinin "Correlation ID ve Trace Context" yazısında anlatılan yapının mikroservis karşılığı bu; production'da aynı sorgu log backend'inde trace id ile yapılıyor.

Trace tek bir siparişi anlatıyor; "dakikada kaç sipariş, checkout ne kadar sürüyor, ödemelerin yüzde kaçı reddediliyor" soruları metric ister. Ordering'e IMeterFactory ile bir Meter ekledik:

// Business metric'ler: kaç sipariş geliyor, checkout ne kadar sürüyor ve nasıl bitiyor.
// Tag'lerin olası değerleri az: bir sonuç ve bir sebep kategorisi; asla sipariş id'si ya da ISBN değil.
public sealed class CheckoutMetrics
{
    public const string MeterName = "Bookstore.Ordering";

    private readonly Counter<long> ordersPlaced;
    private readonly Histogram<double> checkoutDuration;

    public CheckoutMetrics(IMeterFactory meterFactory)
    {
        Meter meter = meterFactory.Create(MeterName);
        ordersPlaced = meter.CreateCounter<long>("bookstore.orders.placed", unit: "{order}",
            description: "Orders accepted by Ordering (202), before stock and payment are known.");
        checkoutDuration = meter.CreateHistogram<double>("bookstore.checkout.duration", unit: "s",
            description: "From the order being placed to the saga's end: confirmed or cancelled.",
            advice: new InstrumentAdvice<double> { HistogramBucketBoundaries = [0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30, 60, 300, 900] });
    }

Saga onaylanırken ya da iptal edilirken süreyi clock.GetUtcNow() - order.PlacedAtUtc olarak kaydediyor; tag'ler bookstore.checkout.outcome (confirmed, cancelled) ve bookstore.checkout.reason (none, out-of-stock, payment-failed, payment-timeout). Histogram'ın bucket sınırlarını kendimiz verdik, çünkü varsayılan sınırlar milisaniye ölçeğindeki HTTP süreleri için; bizim checkout'umuz 15 dakikaya kadar sürebilir. Payments'ta bookstore.payments.completed sayacı sonucu ve sonucun nereden geldiğini (answer, webhook, reconciliation) tutuyor. Sayacı ilk denemede sağlayıcının charge cevabına koymuştuk ve her ödeme pending olarak sayıldı; sonuç webhook ile geldiği için sayacın yeri de orası. Değerleri dotnet-counters ile canlı process'lerden okuduk; 11'deki tarayıcı senaryoları ve webhook'ların düşürüldüğü bir sipariş sırasında:

bookstore.orders.placed ({order} / 5 sec)[bookstore.currency=TRY]                                                   3
bookstore.checkout.duration (s)[outcome=cancelled;reason=out-of-stock;Percentile=50]                         0.0519
bookstore.checkout.duration (s)[outcome=cancelled;reason=payment-failed;Percentile=50]                       1.1289
bookstore.checkout.duration (s)[outcome=confirmed;reason=none;Percentile=50]                                 1.9355
bookstore.payments.completed ({payment} / 5 sec)[outcome=succeeded;result_source=webhook]                         2
bookstore.payments.completed ({payment} / 5 sec)[outcome=failed;result_source=webhook]                            1
bookstore.payments.completed ({payment} / 5 sec)[outcome=succeeded;result_source=reconciliation]                  1
bookstore.checkout.duration (s)[outcome=confirmed;reason=none;Percentile=50]                                14.4844

Son iki satır aynı olayı iki taraftan anlatıyor: webhook gelmeyince sonucu reconciliation buldu ve o siparişin checkout'u 14,5 saniye sürdü. result_source=reconciliation'ın payı artıyorsa webhook'lar yolda kayboluyor demek; bu, tek tek trace'lere bakarak fark edilmez. Satırlar okunur olsun diye tag adlarındaki bookstore.checkout. ve bookstore.payment. öneklerini kısalttık.

.NET 11 Notu: ASP.NET Core'un Kendi Span Attribute'ları

.NET 11 ile ASP.NET Core, Microsoft.AspNetCore activity source'undaki HTTP server span'ına OpenTelemetry'nin HTTP semantic convention attribute'larını kendisi ekliyor; .NET 10'da bu işi OpenTelemetry.Instrumentation.AspNetCore paketi yapıyor. Aynı küçük uygulamayı hiçbir OpenTelemetry paketi olmadan, yalnız bir ActivityListener ile .NET 10 ve .NET 11 SDK'larıyla çalıştırdık:

10.0.13 Microsoft.AspNetCore.Hosting.HttpRequestIn "Microsoft.AspNetCore.Hosting.HttpRequestIn":
11.0.0 Microsoft.AspNetCore.Hosting.HttpRequestIn "GET /api/v1/books/{isbn}": client.address=127.0.0.1, network.peer.address=127.0.0.1, network.peer.port=51690, server.address=127.0.0.1, server.port=51689, http.request.method=GET, url.scheme=http, url.path=/api/v1/books/9780141439587, http.response.status_code=200, network.protocol.version=1.1, http.route=/api/v1/books/{isbn}

.NET 10'da span'ın adı ve attribute'ları boş; .NET 11'de ad route şablonundan geliyor ve attribute'lar dolu. Bookstore'u .NET 11'e yükselttiğinde ServiceDefaults'taki AddAspNetCoreInstrumentation() yerine AddSource("Microsoft.AspNetCore") yetebilir. Paketi kaldırmadan önce ondan başka ne aldığına bak: bizim ServiceDefaults'umuz health check isteklerini Filter ile trace dışında bırakıyor ve bu seçenek paketten geliyor. Attribute'ları istemiyorsan Microsoft Learn'ün "What's new in ASP.NET Core 11" sayfası Microsoft.AspNetCore.Hosting.SuppressActivityOpenTelemetryData AppContext switch'ini veriyor.

Üretimde Dikkat

Dashboard lokal bir araç. Aspire dashboard'u telemetriyi bellekte tutuyor ve yeniden başlayınca her şey gidiyor. Production'da service'ler OTLP ile bir OpenTelemetry Collector'a gönderir, collector trace'leri Tempo'ya, log'ları Loki'ye, metric'leri Prometheus'a yazar ve hepsi Grafana'da birleşir; kurulumu Observability serisinde. Kodda değişen tek şey OTEL_EXPORTER_OTLP_ENDPOINT.

Sampling kararı ver. Her siparişte 81 span var; günde 800 sipariş için sorun değil, kampanya döneminin dakikada 120 siparişinde maliyet büyür. Head sampling (trace'in başında karar vermek) hatalı trace'leri de atabilir; tail sampling (trace bittikten sonra collector'da karar vermek) hataları ve yavaşları tutup gerisini seyreltmeye izin veriyor.

Span'larda kişisel veri olmasın. SqlClient span'ları SQL metnini, ASP.NET Core span'ları kullanıcının tarayıcı bilgisini (user_agent.original) taşıyor ve bizim log'larımızdan biri e-posta adresi yazıyor. Telemetri backend'ine kimin erişebildiğini ve ne kadar saklandığını buna göre belirle.

Metric tag'lerinin olası değer sayısını küçük tut. bookstore.checkout.reason'a iptal sebebinin metnini ("Out of stock: 9781400079988") koysaydık her ISBN (kitabın uluslararası standart numarası) yeni bir zaman serisi açardı. Sebep metni log'a, kategorisi metric'e.

Sık Düşülen Tuzaklar

Messaging library'nin ActivitySource'unu eklemeyi unutmak. HTTP ve SQL span'ları gelince trace tamam sanılıyor; asıl iş mesajlarda.

Arka plan job'larında trace'in kopmasını beklememek. Timer'dan başlayan iş yeni bir trace açar; context'i veriyle birlikte saklamadıysan iki trace'i ancak iş anahtarıyla eşleştirebilirsin.

Deadline'ın neyi kapsadığını bilmemek. Token alma, DNS çözümleme ve bağlantı kurma da çağrının süresine giriyor; trace bunu gösteriyor, log göstermiyor.

Histogram'ı varsayılan bucket'larla bırakmak. Saniyeler ya da dakikalar süren bir iş akışında bütün ölçümler son bucket'a düşer ve percentile'lar anlamsızlaşır.

Business metric'i yanlış yerde saymak. Bizim ilk sayacımız gibi, sonucun henüz belli olmadığı yerde sayılan bir metric her şeyi "pending" gösterir.

Küçük Bir Deneme

★☆☆ Dashboard'da bir checkout trace'i aç ve SQL span'larına bak. Bir handler'da kaç SQL komutu çalışıyor ve bunların kaçı Wolverine'in inbox/outbox tablolarına gidiyor?

★★☆ Reconciliation job'ını trace'e bağla: Payment'a ilk isteğin traceparent'ını kaydet, job'da her ödeme için bir Activity aç ve kaydedilen context'i ActivityLink olarak ekle. Dashboard'da link'i görebiliyor musun?

★★★ Ordering'in Checkout:PaymentTimeout ayarını 5 saniye yap ve sahte sağlayıcıya 5 saniyelik gecikme ver (POST /simulate/response-delay/5000). PaymentSucceeded ile CheckoutTimedOut aynı anda geldiğinde trace'te saga'nın Version çakışmasını ve Wolverine'in retry'ını bul.

Artık bir siparişin yolunu tek bir trace'te, işin sağlığını da metric'lerde görüyoruz. Ama bunların hepsini elle yaptığımız denemelerle doğruladık. Bir sonraki yazıda bu denemeleri otomatik hâle getiriyoruz: Testcontainers ile service seviyesinde testler, Aspire.Hosting.Testing ile bütün sistemi ayağa kaldıran uçtan uca bir checkout testi, Pact ile BFF ve Catalog arasında contract testi ve event contract'ları için şema testleri.