Loglama Yanıtı Bozarsa: .NET 11 HttpLogging’de ArrayPool Hatası

Bir loglama middleware'i, uygulamanızın ürettiği yanıtı değiştirebilir mi? Çoğumuzun cevabı muhtemelen "hayır" olur. Biz de öyle düşünüyorduk.

Şirketimizde servislerimizi .NET 11'e taşımak için gerekli geliştirmeleri yaptık. Happy path senaryolarını test ettiğimizde herhangi bir problem görmedik. Ardından servis genelinde bir sorun olup olmadığını anlamak için otomasyon testlerini çalıştırdık ve sonuçlar bizi şaşırttı: birbirinden farklı endpoint'lerden hata almaya başladık. Detaylı incelememiz sonucunda response'ların içeriğinin değiştiğini fark ettik. Kodu incelememize rağmen sorunun nereden kaynaklandığından emin olamadık.

Beklediğimiz response aşağıdaki gibiydi (kısaltılmış hali):

{
  "openInspections": 128,
  "completedThisWeek": 342,
  "overdue": 7,
  "recent": [
    {
      "code": "INS-20260001",
      "title": "Inspection 01",
      "status": "Open"
    }
  ]
}

Ancak otomasyon testlerinde paralel request'ler gönderdiğimizde aşağıdakine benzer response'lar gelmeye başladı:

{"openInspections":128,"completedThisWeek":342,"overdue":7,"recent":[{"code":"INS-20260001","title":"Inspection 01","status":"Open"},{"code":"INS-20260002","title":"Inspection 02","status":"Open"},{"code":"INS-20260003","title":"Inspection 03","status":"Overdue"},{"code":"INS-20260004","title":"Inspection 04","status":"Open"},{"code":"INS-20260005","title":"Inspection 05","status":"Open"},{"code":"INS-20260006","title":"Inspection 06","status":"Overdue"},{"code":"INS-20260007","title":"Inspection 07","status":"Open"},{"code":"INS-20260008","title":"Inspection 08","status":"Open"},{"code":"INS-20260009","title":"Inspection 09","status":"Overdue"},{"code":"INS-20260010","title":"Inspection 10","status":"Open"},{"code":"INS-20260011","title":"Inspection 11","status":"Open"},{"code":"INS-20260012","titl{"openInspections":128,"completedThisWeek":342,"overdue":7,"recent":[{"code":"INS-20260001","title":"Inspection 01","status":"Open"},{"code":"INS-20260002","title":"Inspection 02","status":"Open"},{"code":"INS-20260003","title":"Inspection 03","status":"Overdue"},{"code":"INS-20260004","title":"Inspection 04","status":"Open"},{"code":"INS-20260005","title":"Inspection 05","status":"Open"},{"code":"INS-20260006","title":"Inspection 06","status":"Overdue"},{"code":"INS-20260007","title":"Inspection 07","status":"Open"},{"code":"INS-20260008","title":"Ins

Görüldüğü gibi response "titl kelimesinin ortasında kesiliyor ve kendini baştan tekrar etmeye başlıyor. Bazı response'larda ise kesilen noktadan sonra başka bir request'in response'u geliyordu. İşin ilginç yanı, status code 200, Content-Type application/json ve body'nin uzunluğu da beklenen uzunlukla birebir aynıydı. Sorunu ancak JSON'ı parse etmeye çalıştığımızda fark edebiliyorduk.

Sorun tek bir endpoint'te olsaydı o endpoint'e odaklanabilirdik. Ancak testleri farklı zamanlarda çalıştırdığımızda sorunun onlarca endpoint'te ortaya çıktığını gördük.

Sorunu çözmek için response üzerinde işlem yapan middleware'leri inceledik, hatta kapattık; sorun çözülmedi. Loglama için kullandığımız kütüphaneyi kapattık; sorun devam etti. En son ASP.NET Core'un HTTP Logging middleware'ini kapattığımızda sorunun ortadan kalktığını gördük. Bu bizi oldukça şaşırttı. Üstelik aynı servisi .NET 10'a geri döndürdüğümüzde testler sorunsuz çalışıyor, .NET 11'e geçtiğimizde ise sorunlar yeniden başlıyordu.

Bunun üzerine araştırmaya başladık. ASP.NET Core'un GitHub reposunda HTTP Logging ile ilgili dotnet/aspnetcore#65147 numaralı PR'ın merge edildiğini gördük. PR'daki değişiklikleri incelediğimizde şu kısım dikkatimizi çekti:

public HttpLoggingMiddleware(
        RequestDelegate next,
        IOptionsMonitor<HttpLoggingOptions> options,
        ILogger<HttpLoggingMiddleware> logger,
        IEnumerable<IHttpLoggingInterceptor> interceptors,
        ObjectPool<HttpLoggingInterceptorContext> contextPool,
        ObjectPool<ResponseBufferingStream> responseBufferingStreamPool,
        TimeProvider timeProvider)

HttpLoggingMiddleware'in constructor'ına ObjectPool<ResponseBufferingStream> responseBufferingStreamPool şeklinde yeni bir parametre eklenmiş. .NET 10'da böyle bir parametre yok.

Havuza dönen stream, eski bir adresi unutmuyor

Response body'yi loglayabilmek için HttpLogging middleware'i, Response.Body'yi ResponseBufferingStream adlı bir stream ile sarmalıyor. Uygulamanın yazdığı her byte önce bu stream'e geliyor; stream bu byte'ların bir kopyasını log için kendi buffer'ına alıyor, ardından asıl byte'ları Kestrel'e iletiyor. Log için tutulan buffer'lar da ArrayPool<byte>.Shared üzerinden kiralanıyor.

.NET 10'da her request için yeni bir ResponseBufferingStream oluşturuluyordu. PR #65147, allocation'ları azaltmak için bu stream'leri bir ObjectPool'da tutup request'ler arasında yeniden kullanmaya başladı. Yani bir request'in kullandığı stream, işi bittiğinde havuza dönüyor ve sonraki bir request'e veriliyor. Fikir olarak mantıklı. Ancak bir stream'i yeniden kullanacaksanız, önceki kullanımdan kalan her durumu sıfırlamanız gerekir.

ResponseBufferingStream'in türediği BufferingStream sınıfında buffer durumu üç alanda tutuluyor: segment listesinin başı (_head), sonu (_tail) ve son segmentte henüz yazılmamış alanı gösteren _tailMemory. Request sonunda body loglandıktan sonra çağrılan Reset() metodu şöyle:

public void Reset()
{
    var segment = _head;
    while (segment != null)
    {
        var returnSegment = segment;
        segment = segment.NextSegment;

        // Kiralanan diziyi ArrayPool<byte>.Shared'e geri verir
        returnSegment.ResetMemory();
    }

    _head = _tail = null;

    _bytesBuffered = 0;
    _tailBytesBuffered = 0;
    // _tailMemory sıfırlanmıyor!
}

Diziler havuza geri veriliyor, _head ve _tail temizleniyor, ancak _tailMemory hâlâ az önce havuza geri verilen dizinin içini gösteriyor. Stream havuza dönerken çağrılan ResetForPool() ve bir sonraki request için çağrılan Initialize() de bu alana dokunmuyor.

.NET 10'da bu bir sorun değildi, çünkü stream request bitince çöpe gidiyordu. Havuzlamayla birlikte ise bir sonraki request, önceki request'ten kalan _tailMemory ile başlıyor. Response'a yazılan her byte önce log kopyası için CommonWrite'tan geçiyor, Kestrel'e ise ancak ondan sonra iletiliyor. CommonWrite da kopyalamayı önce bu alana yapmayı deniyor:

public override async ValueTask WriteAsync(ReadOnlyMemory<byte> buffer, CancellationToken cancellationToken = default)
{
    await OnFirstWriteAsync();
    CommonWrite(buffer.Span);                               // 1. Log için kopyala

    await _innerStream.WriteAsync(buffer, cancellationToken); // 2. Kestrel'e gönder
}

private void CommonWrite(ReadOnlySpan<byte> span)
{
    var remaining = _limit - _bytesBuffered;
    var innerCount = Math.Min(remaining, span.Length);

    if (_logBody && innerCount > 0)
    {
        var slice = span.Slice(0, innerCount);
        if (slice.TryCopyTo(_tailMemory.Span)) // _tailMemory artık bize ait olmayan bir diziyi gösteriyor olabilir
        {
            _tailBytesBuffered += innerCount;
            _bytesBuffered += innerCount;
            _tailMemory = _tailMemory.Slice(innerCount);
        }
        else
        {
            BuffersExtensions.Write(this, slice);
        }
    }
}

Kısacası, artık bize ait olmayan ve ArrayPool'da başka birine kiralanmış olabilecek bir diziye yazıyoruz. Literatürdeki adıyla bu bir use-after-return hatası.

Adım adım ne oluyor?

Yukarıdaki bozuk response'u adım adım takip edelim:

Request A (POST /api/auth/login) 810 byte'lık bir response üretiyor. HttpLogging bu 810 byte'ı log için ArrayPool'dan kiraladığı 4096 byte'lık X dizisine kopyalıyor. Request sonunda body loglanıyor, Reset() çağrılıyor ve X havuza geri veriliyor. Ancak _tailMemory hâlâ X[810..]'u gösteriyor.
Stream ObjectPool'a dönüyor ve Request B'ye (GET /api/dashboard) veriliyor. _tailMemory hâlâ X[810..].
Request B'nin JSON'ı yazılırken, response'u yazan bileşen (PipeWriter) ArrayPool<byte>.Shared'den bir dizi kiralıyor ve aynı X dizisini alıyor. Bu çok olası, çünkü X aynı thread/core üzerinde az önce havuza bırakılmıştı. 1368 byte'lık dashboard JSON'ı X[0..1368] aralığına yazılıyor.
Bu byte'lar HttpLogging stream'ine geldiğinde, CommonWrite log kopyasını Kestrel'e göndermeden önce X[810..]'a yazıyor. Kaynak X[0..1368], hedef X[810..]: aynı dizinin üst üste binen iki bölgesi.
Kopyalamadan sonra X[810..1368] aralığında artık JSON'ın ilk 558 byte'ı var. Kestrel'e giden buffer da aynı X dizisi olduğu için client, ilk 810 byte'ı doğru, kalanı JSON'ın başından tekrar eden bir response alıyor.

810 rastgele bir sayı değil; bir önceki response'un, yani login'in uzunluğu. Bizim ortamımızda bu sayı 194'tü, yani Kubernetes'in sürekli çağırdığı /health-alive endpoint'inin response uzunluğu.

X dizisini aynı request değil de o anda çalışan başka bir request kiralamışsa, bu sefer o request'in verisi eziliyor. Bir kullanıcının menü response'unun içinde başka bir request'in login response'u, yani access token'ı çıkabiliyor. Dolayısıyla bu sadece "bozuk JSON" değil, request'ler arası veri sızıntısı da yaratabilen bir hata.

Peki neden sadece yük altında?

Hatanın ortaya çıkması için uygulamanın ArrayPool'dan tam olarak o diziyi alması gerekiyor. ArrayPool<byte>.Shared dizileri thread ve core bazında önbelleğe aldığı için bu, request'ler aynı core üzerinde art arda işlendiğinde çok daha olası hale geliyor. Happy path testlerinde tek tük gelen request'lerde bu durum nadiren oluşuyor.
Kubernetes'te CPU limiti verilmiş container'larda Environment.ProcessorCount genellikle 1 veya 2 oluyor. Core sayısı azaldıkça aynı dizinin geri gelme olasılığı artıyor. Bu yüzden sorun bizim makinelerimizde daha seyrek, UAT ortamında ise sık görülüyordu.
Uygulama loglarında bozulan request'lerin ResponseBody alanı boş görünüyordu. Bunun nedeni de aynı: veri _head segmentine değil, eski _tailMemory'ye yazıldığı için log tarafında okunacak bir şey kalmıyor. Yani logda boş body, client'ta ise bozuk body görüyorduk.

Bu sorunu yaşayan sadece biz değiliz

Rocket Surgeons Guild'in açık kaynak projesi LaunchPad'de de aynı sorun yaşanmış. 1 Kasım 2026 tarihli commit'te, net11.0 üzerinde CI'da çalışan testlerde bir request'in body'sinde başka bir testin response'unun, bir response'ta ise önceki response'un byte'larının görüldüğü anlatılıyor. Yapılan değişiklik de bizim bulduğumuz geçici çözümle birebir aynı: HTTP Logging'de ResponseBody alanını kapatmak.

Bu commit'in önemli bir detayı var: LaunchPad testleri Kestrel değil, TestServer üzerinde çalışıyor. Yani sorun sunucu, ağ, reverse proxy ya da container altyapısıyla ilgili değil. Doğrudan HttpLogging middleware'inin içinde.

Sorunu izole bir projede tekrar ürettik

Sorunun bizim koda, kullandığımız loglama kütüphanesine ya da Keycloak entegrasyonumuza bağlı olmadığından emin olmak için sıfırdan bir örnek proje hazırladık. Projede MVC controller'lar, bir minimal API endpoint'i, bir health check ve request/response body'lerini loglayan standart HttpLogging konfigürasyonu var. Aynı kodu .NET 11 ve .NET 10 container'larında, cpus: 0.5 limitiyle çalıştırıp k6 ile yük verdik. k6 script'i her response'u beklenen body ile byte byte karşılaştırıyor.

Hedef	Runtime	Kontrol edilen response	Bozuk response
.NET 11	11.0.0-rc.3	62.692	2.678 (%4,3)
.NET 10	10.0.12	73.477	0
.NET 11 + `ResponseBody` loglaması kapalı	11.0.0-rc.3	88.612	0

Bozuk response'ların hepsi 200 döndü, hepsinin uzunluğu doğruydu ve hiçbiri geçerli JSON değildi. Örnek proje, k6 script'i ve hatayı yük olmadan deterministik olarak üreten minimal repro'ya buradan ulaşabilirsiniz.

Bu metriklere nasıl ulaştık

Aşağıdaki k6 script’i, uygulamayı açan kullanıcıları taklit ediyor: her sanal kullanıcı sırayla login, menus, permissions ve dashboard endpoint’lerini çağırıyor. Aynı anda Kubernetes’in kubelet’i gibi saniyede iki kez /health-alive çağrılıyor. Script, yük başlamadan önce her endpoint’in beklenen response’unu öğreniyor; yük sırasında da her response’u bununla byte byte karşılaştırıyor. Tek bir bozuk response bile gelirse test başarısız oluyor.

import http from 'k6/http';
import { check, fail, sleep } from 'k6';
import exec from 'k6/execution';
import { Counter } from 'k6/metrics';

const BASE_URL = __ENV.BASE_URL || 'http://localhost:5011';
const VUS = parseInt(__ENV.VUS || '20');
const DURATION = __ENV.DURATION || '60s';
const SAMPLE_VUS = 5; // only the first few VUs print a corrupted body, to keep the output readable

const ENDPOINTS = {
  login: {
    method: 'POST',
    path: '/api/auth/login',
    body: JSON.stringify({ email: 'user@example.com', password: 'not-a-real-password' }),
  },
  menus: { method: 'GET', path: '/api/users/current/menus' },
  permissions: { method: 'GET', path: '/api/users/current/permissions' },
  dashboard: { method: 'GET', path: '/api/dashboard' },
  health: { method: 'GET', path: '/health-alive' },
};
const NAMES = Object.keys(ENDPOINTS);

const checkedBodies = new Counter('checked_bodies');
const corruptedBodies = new Counter('corrupted_bodies');
const invalidJson = new Counter('invalid_json_bodies');

const thresholds = { corrupted_bodies: ['count==0'] };
for (const name of NAMES) {
  // Per-endpoint thresholds make k6 show per-endpoint numbers in the summary.
  thresholds[`corrupted_bodies{endpoint:${name}}`] = ['count==0'];
  thresholds[`checked_bodies{endpoint:${name}}`] = ['count>=0'];
}

export const options = {
  discardResponseBodies: false,
  thresholds,
  scenarios: {
    users: {
      executor: 'constant-vus',
      vus: VUS,
      duration: DURATION,
      exec: 'userJourney',
    },
    kubelet: {
      executor: 'constant-arrival-rate',
      rate: 2,
      timeUnit: '1s',
      duration: DURATION,
      preAllocatedVUs: 2,
      exec: 'probe',
    },
  },
};

function send(name) {
  const e = ENDPOINTS[name];
  const params = { headers: { 'Content-Type': 'application/json' }, tags: { endpoint: name } };
  return http.request(e.method, BASE_URL + e.path, e.body || null, params);
}

// Learn the expected bodies before the load starts. Each endpoint is called several times and the
// most frequent valid JSON body wins, so a single corrupted response cannot become the reference.
export function setup() {
  let runtime = null;
  for (let i = 0; i < 30 && runtime === null; i++) {
    const res = http.get(`${BASE_URL}/runtime`);
    if (res.status === 200) runtime = res.body;
    else sleep(1);
  }
  if (runtime === null) fail(`${BASE_URL} is not reachable`);
  console.log(`Target: ${BASE_URL} ${runtime}`);

  const expected = {};
  for (const name of NAMES) {
    const votes = {};
    for (let i = 0; i < 7; i++) {
      const body = send(name).body;
      if (isJson(body)) votes[body] = (votes[body] || 0) + 1;
    }
    expected[name] = Object.keys(votes).sort((a, b) => votes[b] - votes[a])[0];
    console.log(`Expected ${name}: ${expected[name].length} bytes`);
  }
  return expected;
}

let samplesPrinted = 0;

function verify(name, res, expected) {
  const body = res.body || '';
  const want = expected[name];
  const ok = res.status === 200 && body === want;

  checkedBodies.add(1, { endpoint: name });
  check(res, { [`${name}: body is intact`]: () => ok });
  if (ok) return;

  corruptedBodies.add(1, { endpoint: name });
  if (!isJson(body)) invalidJson.add(1, { endpoint: name });

  if (exec.vu.idInTest <= SAMPLE_VUS && samplesPrinted++ < 1) {
    console.warn(describe(name, res.status, body, expected));
  }
}

// Explains what a corrupted body looks like: where it diverges, whether it restarts from its own
// first bytes (self-overlap) or contains another endpoint's body (cross-request leak).
function describe(name, status, body, expected) {
  const want = expected[name];
  let diff = 0;
  while (diff < body.length && diff < want.length && body[diff] === want[diff]) diff++;

  let cause = 'unknown';
  const restart = body.indexOf(want.substring(0, 24), 1);
  if (restart > 0) cause = `body restarts from its first byte at offset ${restart}`;
  for (const other of NAMES) {
    if (other === name) continue;
    const at = body.indexOf(expected[other].substring(0, 24));
    if (at >= 0) cause = `contains the /${other} body at offset ${at}`;
  }

  const from = Math.max(0, diff - 40);
  return [
    `CORRUPTED ${name}: status=${status} expected=${want.length}B received=${body.length}B`,
    `  first difference at byte ${diff}; ${cause}`,
    `  ...${body.substring(from, diff + 60)}...`,
  ].join('\n');
}

function isJson(body) {
  try {
    JSON.parse(body);
    return true;
  } catch (_) {
    return false;
  }
}

export function userJourney(expected) {
  for (const name of ['login', 'menus', 'permissions', 'dashboard']) {
    verify(name, send(name), expected);
  }
}

export function probe(expected) {
  verify('health', send('health'), expected);
}

Ortamı simüle etmek içinde Docker'dan faydalandık. Docker Compose dosyamızın içeriğide aşağıdaki gibi:

services:
  api-net11:
    build:
      context: ./src/SampleApi
      args: { RUNTIME_TAG: "11.0", TFM: net11.0 }
    cpus: 0.5
    ports: ["5011:8080"]

  api-net10:
    build:
      context: ./src/SampleApi
      args: { RUNTIME_TAG: "10.0", TFM: net10.0 }
    cpus: 0.5
    ports: ["5010:8080"]

  # .NET 11 with the workaround: response bodies are not logged.
  api-net11-workaround:
    build:
      context: ./src/SampleApi
      args: { RUNTIME_TAG: "11.0", TFM: net11.0 }
    cpus: 0.5
    environment:
      LOG_RESPONSE_BODY: "false"
    ports: ["5012:8080"]

Son olarak hazırlamış olduğumuz k6 testlerini aşağıdaki bash script'i ile çalıştırdık:

#!/usr/bin/env bash
set -euo pipefail
cd "$(dirname "$0")"

DURATION=${DURATION:-60s}
VUS=${VUS:-20}

docker compose up -d --build

run_k6() {
  local url=$1
  if command -v k6 > /dev/null; then
    k6 run -e BASE_URL="$url" -e DURATION="$DURATION" -e VUS="$VUS" load/load-test.js
  else
    # No local k6: run it in a container and reach the host ports through host.docker.internal.
    docker run --rm -i --add-host=host.docker.internal:host-gateway grafana/k6 run \
      -e BASE_URL="${url/localhost/host.docker.internal}" -e DURATION="$DURATION" -e VUS="$VUS" - < load/load-test.js
  fi
}

for target in "api-net11 http://localhost:5011" "api-net10 http://localhost:5010" "api-net11-workaround http://localhost:5012"; do
  set -- $target
  echo
  echo "################ $1 ($2) ################"
  run_k6 "$2" || true # k6 exits 99 when the corrupted_bodies threshold is crossed
done

echo
echo "Done. Stop the containers with: docker compose down"

Çözüm önerileri

1. Kısa vadede: Response body loglamasını kapatın

.NET 11'de, sorun ASP.NET Core tarafında düzeltilene kadar HttpLoggingFields.ResponseBody alanını kapatmak en güvenli yol. Request body, header'lar, status code ve süre gibi diğer alanları loglamaya devam edebilirsiniz:

builder.Services.AddHttpLogging(options => {    options.LoggingFields = HttpLoggingFields.All & ~HttpLoggingFields.ResponseBody; });

Bu ayarla middleware stream'i yine sarmalıyor, ancak response body'yi loglamadığı için CommonWrite içindeki kopyalama hiç çalışmıyor. Örnek projede bu ayarla 88.612 response'ta tek bir bozulma görmedik.

IHttpLoggingInterceptor kullanıyorsanız, interceptor'ın ResponseBody alanını tekrar açmadığından emin olun. Response body loglaması zorunluysa, bu ihtiyacı geçici olarak uygulama katmanında (örneğin belirli endpoint'ler için bir action filter ile) karşılamayı düşünebilirsiniz.

2. Alternatif: .NET 10'da kalın

Response body loglaması sizin için vazgeçilmezse, düzeltme yayınlanana kadar .NET 10'da kalmak da bir seçenek. Bizim testlerimizde aynı kod .NET 10'da hiç bozulmadı.

Çıkardığımız dersler

Happy path testleri yetmiyor. Bu hata tek tek gönderilen request'lerde neredeyse hiç ortaya çıkmıyor. Runtime geçişlerinde paralel yük testi çalıştırmak, sürüm yükseltme kontrol listemizin kalıcı bir parçası oldu.
Status code'a değil, içeriğe bakın. Bozuk response'ların hepsi 200 döndü ve uzunlukları doğruydu. Yük testlerinde response body'yi beklenen içerikle karşılaştırmak, bu tür hataları yakalamanın tek yolu.
Test ortamı production'a benzemeli. Hata CPU limiti olan container'larda çok daha sık ortaya çıkıyor. Testleri production'daki kaynak limitleriyle çalıştırmak, bu tür sorunları daha erken yakalamamızı sağlardı.
"Sadece gözlemleyen" kod da çıktıyı etkileyebilir. Bir loglama middleware'i, paylaşılan bir bellek havuzunu yanlış kullandığında response'u değiştirebiliyor. Havuzlama gibi performans optimizasyonları, ömür yönetimi doğru yapılmazsa bulması çok zor hatalara yol açabiliyor.
Geri dönmek de bir debug yöntemi. Aynı kodu .NET 10 ile çalıştırmak ve bileşenleri tek tek kapatmak, sorunu birkaç adımda HttpLogging'e kadar daraltmamızı sağladı. Oradan sonrası, ilgili PR'ı okumaktı.

Bulgularımızı ve reproduce edilebilir örnek projeyi, Türkiye’deki Microsoft Developer Technologies MVP’lerinden Murat Dinç ile paylaştık; kendisi konuyla ilgili Microsoft’a bir ticket açtı. Gelişmeleri takip edip bu yazıyı güncelleyeceğim.

Başta sorduğumuz soruya dönersek: Evet, bir loglama middleware'i uygulamanızın ürettiği response'u değiştirebilir. Üstelik bunu hiçbir hata fırlatmadan, 200 OK ile yapabilir.