خطای ۵۰۰ در پروداکشن: از گزارش کاربر تا خط کد

این مقاله یک ماجراست، نه فهرست توصیه. ماجرایی که تکه‌هایش را بارها در سیستم‌های مختلف دیده‌ام و اینجا با جزئیات تغییرداده کنار هم گذاشته‌ام: یک گزارش کاربر، دو ساعت جستجوی بی‌نتیجه، و بعد همان ماجرا دوباره، این بار با لاگ‌هایی که از اول باید وجود می‌داشتند. روش کلی را در راهنمای عیب‌یابی در پروداکشن گفته‌ام؛ اینجا می‌خواهم ببینید همان روش در یک مورد مشخص چه شکلی دارد.

گزارش: «پرداخت نشد»

ساعت ۱۱ صبح یک روز کاری، پیامی از پشتیبانی می‌رسد: «مشتری می‌گوید دیروز عصر خواسته سفارشش را ثبت کند، روی دکمهٔ پرداخت زده و صفحه نوشته خطایی رخ داد. دو بار امتحان کرده. اسکرین‌شات هم فرستاده.»

اسکرین‌شات یک پیام قرمز عمومی را نشان می‌دهد و نه هیچ چیز دیگر. پس داده‌های ما این‌هاست: «دیروز عصر»، «صفحهٔ پرداخت»، و شمارهٔ موبایل مشتری که پشتیبانی دارد. با همین باید به یک خط کد برسیم.

نسخهٔ اول: دو ساعت جستجو

در نسخهٔ اول ماجرا، سیستم این‌طور لاگ می‌نوشت. Nginx لاگ دسترسی داشت و برنامه یک کنترلر پرداخت با این شکل:

[HttpPost("checkout")]
public async Task<IActionResult> Checkout(CheckoutRequest request)
{
    try
    {
        var order = await _orders.CreateAsync(request);
        return Ok(order);
    }
    catch (Exception ex)
    {
        _logger.LogError("Checkout failed: " + ex.Message);
        return StatusCode(500);
    }
}

این کد سه مشکل دارد که هر کدام بعداً یک ساعت وقت می‌گیرد:

• stack trace دور ریخته شده. فقط ex.Message لاگ شده. پیام برای NullReferenceException می‌شود «Object reference not set to an instance of an object» — که دقیقاً هیچ چیز نمی‌گوید.
• هیچ زمینه‌ای نیست. نه شناسهٔ کاربر، نه شناسهٔ سبد، نه کد تخفیف. خط لاگ را نمی‌شود به مشتری وصل کرد.
• به کاربر چیزی داده نشده که گزارش کند. پاسخ ۵۰۰ خالی است، پس پشتیبانی هم چیزی برای فرستادن ندارد.

آنچه رخ داد قابل پیش‌بینی بود. در لاگ Nginx، بین ساعت ۱۷ تا ۲۰ دیروز، ۴۳ پاسخ ۵۰۰ روی /api/checkout بود. در لاگ برنامه، ۴۳ خط «Checkout failed: Object reference not set…» روی سه سرور. با تطبیق IP مشتری (که از روی شماره موبایل و جدول ورودها پیدا شد) دو درخواست او پیدا شد. ولی چرا خطا داده؟ هیچ اطلاعاتی نبود. تیم مجبور شد کد پرداخت را خط به خط بخواند و حدس بزند کدام متغیر ممکن است null باشد. دو ساعت بعد، یکی حدس زد که «شاید کد تخفیف».

لاگ‌هایی که باید وجود می‌داشت

پیش از رفتن به نسخهٔ دوم، فهرست چیزهایی که کم بود. این فهرست، به نظرم، حداقل لازم برای هر سرویس HTTP در پروداکشن است:

1. یک خط برای هر درخواست، در پایان آن: متد، الگوی مسیر (نه نشانی کامل با پارامترها)، کد وضعیت، مدت، و شناسهٔ کاربر (یا نسخهٔ هش‌شدهٔ آن).
2. خود exception، کامل، با stack trace، یک بار و فقط یک بار — در لایه‌ای که آن را مدیریت می‌کند.
3. زمینهٔ کسب‌وکاری روی لاگ‌های مسیر حساس: شناسهٔ سفارش، شناسهٔ سبد، کد تخفیف. با سطح درست؛ نه همه‌چیز Error، نه همه‌چیز Debug — معیارش را در سطح‌های لاگ گفته‌ام.
4. trace_id روی همهٔ این خطوط، تا بشود همه را با یک جستجو کنار هم دید، حتی اگر از چند سرویس آمده باشند. چگونگی‌اش را در trace_id و correlation id نوشته‌ام.
5. همان trace_id در پاسخ خطا به کاربر.

و چیزی که نباید باشد: بدنهٔ کامل درخواست پرداخت. شمارهٔ کارت، توکن درگاه و نشانی مشتری جایشان در لاگ نیست؛ چرایی و روشش موضوع یک مقالهٔ جداست.

middleware خطا و ProblemDetails

اولین اصلاح، حذف try/catch از کنترلر است. exceptionی که نمی‌دانید با آن چه کنید را نگیرید؛ بگذارید بالا برود تا middleware خطای ⁦ASP.NET Core⁩ آن را بگیرد. آن middleware خودش exception را کامل، با stack trace، در دستهٔ Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware لاگ می‌کند و پاسخ استاندارد برمی‌گرداند. در ⁦.NET 8⁩ و 9، پیکربندی‌اش این است:

using System.Diagnostics;

var builder = WebApplication.CreateBuilder(args);

builder.Services.AddControllers();
builder.Services.AddProblemDetails(options =>
{
    options.CustomizeProblemDetails = context =>
    {
        context.ProblemDetails.Extensions["traceId"] =
            Activity.Current?.TraceId.ToString() ?? context.HttpContext.TraceIdentifier;
    };
});

var app = builder.Build();

if (!app.Environment.IsDevelopment())
{
    app.UseExceptionHandler();
}
app.UseStatusCodePages();

app.MapControllers();
app.Run();

AddProblemDetails باعث می‌شود پاسخ‌های خطا در قالب استاندارد ProblemDetails (RFC 9457) برگردند، و UseExceptionHandler() بدون آرگومان از همان سرویس استفاده می‌کند. از ⁦.NET 9⁩ به بعد، ⁦ASP.NET Core⁩ خودش هم شناسه‌ای به نام traceId در این پاسخ می‌گذارد، ولی مقدارش کل Activity.Id است (قالب traceparent)؛ در ⁦.NET 8⁩ این کار پیش‌فرض نیست. با CustomizeProblemDetails در هر دو نسخه فقط خود trace id را می‌گذارم، چون همان چیزی است که در ابزار لاگ جستجو می‌کنید. پاسخ چیزی شبیه این می‌شود (متن title در نسخه‌های مختلف کمی فرق می‌کند):

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

به آنچه در پاسخ نیست هم دقت کنید: پیام exception و stack trace. این‌ها برای کاربر بی‌فایده و برای مهاجم مفیدند. صفحهٔ خطای توسعه‌دهنده فقط در محیط Development روشن است و باید همان‌جا بماند.

سمت فرانت‌اند هم یک تغییر کوچک لازم است: وقتی پاسخ خطا traceId دارد، آن را زیر پیام خطا نشان دهید — مثلاً «کد پیگیری: 4bf92f35…» — و به پشتیبانی بگویید اولین چیزی که از مشتری می‌پرسند همین کد باشد.

exceptionهایی که معنای کسب‌وکاری دارند (مثل «کد تخفیف منقضی شده») جای دیگری‌اند: آن‌ها را به پاسخ ۴۰۰ یا ۴۲۲ با پیام روشن تبدیل کنید، نه ۵۰۰. اگر منطق مشترکی برای این تبدیل لازم دارید، IExceptionHandler در ⁦.NET 8⁩ جای مناسبی است. ولی ۵۰۰ یعنی «ما خراب کردیم»، و باید با stack trace کامل در لاگ بیاید.

نسخهٔ دوم: پانزده دقیقه

همان ماجرا، با سیستم اصلاح‌شده. این بار اسکرین‌شات مشتری زیر پیام خطا یک کد پیگیری دارد. پشتیبانی کد را می‌فرستد، و توسعه‌دهنده آن را در ابزار لاگ جستجو می‌کند. نتیجه، هفت خط از دو سرویس، به ترتیب زمان:

17:42:08.114 INF  [api]      Checkout started for cart 88213, user u_5f2a, coupon AUTUMN05
17:42:08.130 INF  [pricing]  Applying coupon AUTUMN05 to cart 88213
17:42:08.162 ERR  [pricing]  An unhandled exception has occurred while executing the request.
  System.NullReferenceException: Object reference not set to an instance of an object.
     at Shop.Pricing.CouponService.ApplyAsync(Cart cart, String code) in /src/Pricing/CouponService.cs:line 57
     at Shop.Pricing.Api.PriceController.Quote(QuoteRequest request) in /src/Pricing/Api/PriceController.cs:line 31
17:42:08.170 INF  [pricing]  HTTP POST /quote responded 500 in 41 ms
17:42:08.175 WRN  [api]      Pricing service returned 500 for cart 88213
17:42:08.181 ERR  [api]      An unhandled exception has occurred while executing the request.
  Shop.Api.Clients.PricingUnavailableException: Pricing returned 500
17:42:08.186 INF  [api]      HTTP POST /api/checkout responded 500 in 74 ms

خطای اصلی در سرویس api نیست؛ در سرویس قیمت‌گذاری است، و api فقط پیامد آن را دیده. بدون trace_id مشترک، کسی که فقط لاگ api را نگاه می‌کرد، باید دوباره حدس می‌زد. حالا خط ۵۷ فایل CouponService.cs را داریم:

var coupon = await _coupons.FindAsync(code);
if (coupon is null || coupon.ExpiresAt < _clock.UtcNow)
{
    throw new CouponNotValidException(code);
}

var percent = coupon.Campaign.DiscountPercent;   // line 57

کوپن AUTUMN05 به کمپینی تعلق داشت که دیروز ظهر بایگانی شده بود. بایگانی کمپین، ارتباطش را با کوپن‌ها پاک می‌کرد ولی خود کوپن‌ها را نه. پس کوپن وجود داشت، منقضی نبود، و Campaign آن null بود. نکتهٔ جالب این است که با جستجوی همین نوع خطا در بازهٔ ۲۴ ساعت، معلوم شد همهٔ ۴۳ خطای دیروز همین ریشه را داشتند — یعنی یک باگ، نه ۴۳ مشکل جدا.

اصلاح کد ساده است؛ اصلاح واقعی، رفع ناسازگاری داده هنگام بایگانی است. ولی نکتهٔ این مقاله آنجاست که زمان رسیدن از گزارش تا خط ۵۷، از دو ساعت به پانزده دقیقه رسید، و هیچ‌کس حدس نزد.

یک نکتهٔ کوچک که اغلب نادیده می‌ماند: شمارهٔ خط در stack trace فقط وقتی هست که فایل‌های PDB کنار DLLها منتشر شده باشند. پیش‌فرض ⁦.NET⁩ برای Release ساختن PDB قابل‌حمل است؛ مطمئن شوید فرایند انتشارتان آن‌ها را حذف نمی‌کند.

آنچه از این ماجرا یاد گرفتم

• catch (Exception) در کنترلر تقریباً همیشه اشتباه است. اگر می‌گیرید، با _logger.LogError(ex, "...") لاگ کنید — خود ex را، نه ex.Message.
• یک middleware خطا، یک جا برای لاگ کردن exception و یک قالب پاسخ. نه لاگ تکراری در هر لایه.
• trace_id به کاربر برگردد. گزارشی که کد پیگیری دارد، نصف کار را از قبل انجام داده.
• زمینهٔ کسب‌وکاری (شناسه‌ها، نه داده‌های حساس) روی خطوط مسیرهای مهم.
• لاگ همهٔ سرویس‌ها در یک جا، تا خطای سرویس دوم دیده شود. همین‌جاست که ابزاری مثل LogMug با «همهٔ لاگ‌های این درخواست» و گروه‌بندی خطاهای هم‌ریشه کار را کوتاه می‌کند؛ روش کار با آن را در آموزش دنبال کردن یک درخواست و گروه‌بندی خطاها نوشته‌ام.

قدم بعد: حذف واسطه (به‌زودی)

در نسخهٔ دوم ماجرا هنوز یک واسطهٔ انسانی هست: مشتری باید کد پیگیری را ببیند، پشتیبانی باید آن را بخواهد و به توسعه‌دهنده برساند. در عمل، نیمی از مشتری‌ها اسکرین‌شات نمی‌فرستند.

چیزی که الان در حال ساختنش هستیم، اتصال باگ‌ماگ به LogMug است: ایده این است که وقتی باگ‌ماگ خطای فرانت‌اند یا گزارش باگ کاربر را ثبت می‌کند، trace_id درخواستی که شکست خورده هم کنارش بماند، و از همان گزارش مستقیم به لاگ‌های بک‌اند همان درخواست برسید — بی آنکه کسی کدی را کپی کند. این قابلیت هنوز در دسترس نیست؛ تا آن روز، ProblemDetails با traceId همان کاری را می‌کند که از دست نرم‌افزار برمی‌آید.

منابع و مطالعهٔ بیشتر

• مدیریت خطا در ⁦ASP.NET Core⁩ — مرجع رسمی middleware خطا، IExceptionHandler و صفحهٔ خطای توسعه‌دهنده.
• مدیریت خطا در Web APIهای ⁦ASP.NET Core⁩ — جزئیات ProblemDetails و سفارشی‌سازی آن با CustomizeProblemDetails.
• RFC 9457: Problem Details for HTTP APIs — استانداردی که قالب پاسخ خطا را تعریف می‌کند و جانشین RFC 7807 است.