عیب‌یابی خطا در پروداکشن با لاگ: روش گام‌به‌گام

در این مقاله می‌خوانید

پیش‌نیاز: لاگی که بشود با آن کار کرد
گام ۱: علامت را دقیق بنویسید
گام ۲: بازهٔ زمانی را تنگ کنید
گام ۳: با سرویس و سطح فیلتر کنید
گام ۴: trace_id را دنبال کنید
گام ۵: با اثرانگشت خطا ابعاد را بفهمید
گام ۶: بازتولید کنید
گام ۷: رفع کنید — کوچک و با یک آزمون
گام ۸: تأیید کنید که واقعاً رفع شده
یک نمونهٔ واقعی‌نما از اول تا آخر
گزارش
بازه و نمودار
فیلتر و trace
ابعاد
بازتولید و علت
رفع
تأیید
عادت‌هایی که روش را سریع‌تر می‌کنند
منابع و مطالعهٔ بیشتر

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

چیزی که در این مقاله می‌نویسم، روشی است که طی سال‌ها برای خودم و تیم‌هایی که با آن‌ها کار کرده‌ام جا افتاده: هشت گام ساده که از «یک کاربر شاکی است» شروع می‌شود و به «مطمئنیم دیگر تکرار نمی‌شود» ختم می‌شود. هیچ‌کدام از گام‌ها نبوغ نمی‌خواهد. ارزششان در این است که به ترتیب انجام شوند و هیچ‌کدام جا نیفتد.

پیش‌نیاز: لاگی که بشود با آن کار کرد

روش زیر روی سه فرض بنا شده. اگر هر کدام برقرار نیست، قبل از حادثهٔ بعدی درستش کنید، چون وسط حادثه دیگر وقتش نیست:

لاگ‌ها در یک جا جمع شده‌اند. اگر برای دیدن لاگ هر سرور باید SSH بزنید، گام‌های ۳ و ۴ عملاً ناممکن می‌شوند.
لاگ‌ها ساخت‌یافته‌اند. یعنی شمارهٔ سفارش، شناسهٔ کاربر و نام سرویس فیلدهای جدا هستند، نه تکه‌ای از یک رشتهٔ متنی. دلیلش را در مقالهٔ لاگ ساخت‌یافته مفصل گفته‌ام.
هر خط trace_id دارد. شناسه‌ای که همهٔ خطوط یک درخواست را — در همهٔ سرویس‌ها — به هم وصل می‌کند. راه‌اندازی‌اش با OpenTelemetry را در OpenTelemetry به زبان ساده توضیح داده‌ام.

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

گام ۱: علامت را دقیق بنویسید

گزارش‌ها تقریباً همیشه مبهم می‌رسند: «سایت کار نمی‌کند»، «پرداخت خراب است»، «از دیشب کند شده». اولین کار، تبدیل این جمله به چیزی است که بشود در لاگ دنبالش گشت. پنج سؤال:

چه کسی؟ یک کاربر، چند کاربر، همه؟ اگر یک نفر است، شناسه یا شماره‌اش چیست؟
چه کاری؟ دقیقاً کدام صفحه یا دکمه یا API؟
چه دید؟ پیام خطا، صفحهٔ سفید، چرخش بی‌پایان، یا نتیجهٔ غلط بی‌خطا؟
کِی؟ حدود ساعت — حتی تقریبی.
از کِی؟ همیشه این‌طور بوده یا از یک زمان مشخص شروع شده؟

سؤال آخر از همه مهم‌تر است و کمتر از همه پرسیده می‌شود. «از دیروز ساعت ۱۶» تقریباً همیشه یعنی «از یک تغییر» — یک استقرار، یک تغییر پیکربندی، یک به‌روزرسانی در سرویس بیرونی. اگر جواب این سؤال را دارید، نیمی از راه را رفته‌اید.

یک یادداشت کوتاه با همین پنج جواب بنویسید و در کانال حادثه بگذارید. این کار دو دقیقه وقت می‌گیرد و جلوی این را می‌گیرد که سه نفر سه مسئلهٔ متفاوت را دنبال کنند.

گام ۲: بازهٔ زمانی را تنگ کنید

لاگ بدون بازهٔ زمانی، اقیانوس است. بازه را اول کمی گشاد بگیرید — مثلاً یک ساعت دور زمانی که کاربر گفته — و بعد تنگش کنید. بهترین ابزار برای این کار، نمودار تعداد لاگ در زمان به تفکیک سطح است. چیزهایی که در این نمودار دنبالشان می‌گردم:

یک پله: تعداد Errorها از یک دقیقهٔ مشخص بالا رفته و بالا مانده. تقریباً همیشه یعنی یک تغییر در همان لحظه.
یک قله: جهش کوتاه و برگشت. معمولاً وابستگی بیرونی‌ای که لحظه‌ای افتاده — دیتابیس، درگاه بانک، سرویس پیامک.
یک دره: تعداد کل لاگ‌ها ناگهان کم شده. این از خطاهای زیاد بدتر است: یعنی چیزی اصلاً اجرا نمی‌شود، یا لاگ‌ها دیگر نمی‌رسند.
هیچ: نمودار عادی است. یعنی مشکل یا محدود به یک کاربر است، یا خطا لاگ نمی‌شود — که خودش یافتهٔ مهمی است.

بازه را تا جای ممکن تنگ کنید. فرق بین گشتن در یک ساعت و گشتن در سه دقیقه، فرق بین ده هزار خط و دویست خط است.

گام ۳: با سرویس و سطح فیلتر کنید

حالا در همان بازه، فیلتر سطح را روی error و fatal بگذارید و ببینید خطاها از کدام سرویس‌ها می‌آیند. شمارش هر سرویس اینجا خیلی گویاست: اگر ۹۰ درصد خطاها از یک سرویس است، از همان شروع کنید. اگر بین همه پخش است، احتمالاً مشکل در چیزی است که همه به آن وابسته‌اند — دیتابیس، کش، شبکه، یا سرویس احراز هویت.

دو تله در این گام:

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

اگر کاربر مشخصی گزارش داده، اینجا جای فیلتر روی شناسهٔ اوست — به شرط اینکه آن را به‌صورت فیلد ساخت‌یافته لاگ کرده باشید. با این فیلتر، از ده‌ها هزار خط به چند ده خطِ همان کاربر در همان بازه می‌رسید.

گام ۴: trace_id را دنبال کنید

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

درخواست از کجا آمد و با چه پارامترهایی؟
از کدام سرویس‌ها گذشت؟
اولین چیز غیرعادی کجا بود؟

آن «اولین» را جدی بگیرید. خطای آخر زنجیره معمولاً پیامی کلی است — «Order creation failed». علت واقعی معمولاً چند خط بالاتر و در سرویس دیگری است، اغلب با سطح Warning: یک retry، یک timeout، یک مقدار null که نباید می‌بود. در بیشتر حادثه‌هایی که بررسی کرده‌ام، علت در یک Warning بوده که کسی نخوانده بود.

اگر trace_id ندارید، این گام با تخمین زمان و grep روی شمارهٔ سفارش انجام می‌شود — شدنی است، ولی کند و پرخطاست. این یکی از قوی‌ترین دلایل برای اضافه کردن trace_id است، پیش از حادثهٔ بعدی.

گام ۵: با اثرانگشت خطا ابعاد را بفهمید

تا اینجا یک نمونه از مشکل را فهمیده‌اید. سؤال بعدی این است: این یک مورد است یا هزار مورد؟ و آیا همان مشکل است یا چند مشکل که شبیه هم‌اند؟

اینجا جایی است که گروه‌بندی خطا با اثرانگشت (fingerprint) به کار می‌آید. ایده ساده است: دو خطا «یکی‌اند» اگر نوع exception و چند فریم بالای stack trace در کد خود برنامه یکسان باشد — صرف‌نظر از شمارهٔ خط، شناسهٔ سفارش یا متن پیام که در هر رخداد فرق می‌کند. با این گروه‌بندی می‌فهمید:

این خطا در بازهٔ حادثه چند بار رخ داده و برای چند کاربر.
اولین بار کِی دیده شده — اگر دقیقاً بعد از استقرار دیروز است، علت را تقریباً پیدا کرده‌اید.
آیا روی همهٔ میزبان‌ها هست یا فقط یکی. خطایی که فقط روی web-03 است، بوی پیکربندی یا دیسک آن سرور را می‌دهد، نه کد.

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

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

گام ۶: بازتولید کنید

تا مشکلی را بازتولید نکرده‌اید، مطمئن نیستید آن را فهمیده‌اید. از روی لاگ‌های گام ۴، ورودی دقیق درخواست را بازسازی کنید: کدام endpoint، کدام پارامترها، کدام وضعیت داده. بعد سعی کنید در محیط آزمایشی همان خطا را بگیرید.

چند راه که معمولاً جواب می‌دهد:

همان ورودی، داده‌ای شبیه. اگر خطا برای سفارشی با کد تخفیف و ارسال رایگان رخ داده، سفارشی با همین ترکیب بسازید.
شرایط مرزی. لیست خالی، مقدار null، رشتهٔ خیلی بلند، نویسهٔ فارسی یا ایموجی، عدد منفی، تاریخ شمسی آخر اسفند.
شرایط زمانی. اگر خطا فقط زیر بار رخ می‌دهد، با چند درخواست هم‌زمان امتحان کنید. خطاهای هم‌زمانی (race condition) در یک درخواست تنها خودشان را نشان نمی‌دهند.
وابستگی بیرونی. اگر سرویس بیرونی کند شده بوده، در محیط آزمایشی با تأخیر مصنوعی شبیه‌سازی‌اش کنید.

اگر بازتولید ناممکن است، چیزی کم دارید. به جای حدس زدن، لاگ اضافه کنید: یک لاگ Debug یا Information دقیقاً در نقطه‌ای که شک دارید، با مقادیری که برای تصمیم لازم دارید. استقرار دهید و منتظر رخداد بعدی بمانید. این کار کند به نظر می‌رسد، ولی از سه روز حدس زدن سریع‌تر است.

گام ۷: رفع کنید — کوچک و با یک آزمون

رفع خوب، کوچک است. وسط حادثه وقت بازنویسی ماژول نیست. کمترین تغییری که علت را برطرف می‌کند، به‌اضافهٔ یک آزمون خودکار که دقیقاً همان حالت بازتولیدشده را پوشش دهد. آن آزمون دو ارزش دارد: ثابت می‌کند رفع کار می‌کند، و تضمین می‌کند همین باگ شش ماه بعد با یک refactor برنگردد.

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

گام ۸: تأیید کنید که واقعاً رفع شده

«استقرار موفق بود» به معنی «مشکل حل شد» نیست. بعد از استقرار، همان نمایی را که در گام‌های ۲ و ۵ ساختید دوباره باز کنید:

آیا گروه آن خطا از لحظهٔ استقرار رخداد تازه‌ای دارد؟
آیا نمودار Errorها به سطح پیش از حادثه برگشته؟
آیا خطای تازه‌ای از همان لحظه ظاهر شده؟ رفع‌هایی که مشکل را از یک جا به جای دیگر منتقل می‌کنند کم نیستند.

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

یک نمونهٔ واقعی‌نما از اول تا آخر

این نمونه ترکیبی از چند حادثهٔ واقعی است که جزئیاتش را عوض کرده‌ام؛ عددها مثال‌اند.

گزارش

ساعت ۲۱:۵۰، پشتیبانی پیام می‌دهد: «سه نفر گفته‌اند پول از حسابشان کم شده ولی سفارش ثبت نشده.» پنج سؤال گام ۱: سه کاربر (شماره‌سفارش‌ها را پشتیبانی دارد)؛ کار، پرداخت آنلاین؛ دیده، بعد از برگشت از درگاه بانک صفحهٔ «خطا در ثبت سفارش»؛ زمان، بین ۲۱:۳۰ تا ۲۱:۴۵؛ از کِی، «امروز عصر هم یکی داشتیم».

بازه و نمودار

بازهٔ ۱۸:۰۰ تا ۲۲:۰۰ را باز می‌کنم. نمودار Errorها یک پله دارد: از حدود ۱۷:۲۰ تعداد خطاهای سرویس orders از تقریباً صفر به چند ده در ساعت رسیده. یادداشت کانال استقرار را نگاه می‌کنم: ساعت ۱۷:۱۵ نسخهٔ تازهٔ سرویس orders منتشر شده. مظنون اول همین است، ولی هنوز چیزی ثابت نشده.

فیلتر و trace

فیلتر سطح Error و سرویس orders. پیام غالب این است:

ERROR orders  Failed to confirm order 77104 after payment callback
System.InvalidOperationException: Order 77104 is not in state AwaitingPayment (current: Expired)
   at Shop.Orders.OrderStateMachine.Confirm(Order order)
   at Shop.Orders.PaymentCallbackHandler.HandleAsync(CallbackRequest req)

trace_id یکی از این خطاها را برمی‌دارم و کل درخواست را می‌خوانم:

21:31:02.114 gateway   INFO  POST /payment/callback
21:31:02.120 payments  INFO  Bank callback received, ref=REF-...-913, status=OK
21:31:02.388 payments  INFO  Payment verified with bank for order 77104
21:31:02.401 orders    WARN  Order 77104 expired at 21:30:45 (reservation TTL 15m)
21:31:02.402 orders    ERROR Failed to confirm order 77104 after payment callback

«اولین چیز غیرعادی» همان Warning است: سفارش ۱۷ ثانیه پیش از برگشت کاربر از بانک منقضی شده. کاربر پول داده، بانک تأیید کرده، ولی سفارش دیگر در وضعیتی نیست که بشود تأییدش کرد.

ابعاد

گروه این خطا را باز می‌کنم: از ۱۷:۲۲ امروز، ۴۱ رخداد؛ اولین رخداد هفت دقیقه بعد از استقرار؛ روی همهٔ میزبان‌ها. پیش از امروز هیچ رخدادی ندارد. حالا تقریباً مطمئنم که مشکل از نسخهٔ تازه است.

بازتولید و علت

diff استقرار را نگاه می‌کنیم. در نسخهٔ جدید، مدت رزرو سفارش از پیکربندی خوانده می‌شود و پیش‌فرضش به‌اشتباه ۱۵ دقیقه شده، در حالی که قبلاً در کد ۳۰ دقیقه بود — و کاربرانی که در صفحهٔ بانک رمز پویا را با تأخیر دریافت می‌کنند، به‌راحتی از ۱۵ دقیقه می‌گذرند. در محیط آزمایشی سفارشی می‌سازیم، ۱۶ دقیقه صبر می‌کنیم (یا ساعت را جلو می‌کشیم) و callback را شبیه‌سازی می‌کنیم: همان exception.

رفع

دو تغییر. فوری: برگرداندن مقدار پیش‌فرض به ۳۰ دقیقه و استقرار. اصولی: اگر پرداختی برای سفارش منقضی‌شده تأیید شد، سفارش دوباره فعال شود — یا اگر موجودی دیگر نیست، بازگشت وجه خودکار ثبت شود — به جای exception. یک آزمون برای هر دو حالت. و ۴۱ سفارش آسیب‌دیده را از روی همان گروه خطا فهرست می‌کنیم و به پشتیبانی می‌دهیم تا دستی پیگیری شوند.

تأیید

بعد از استقرار ساعت ۲۲:۴۰، گروه خطا رخداد تازه‌ای ندارد. تا ظهر فردا هم صبر می‌کنیم — شب‌ها ترافیک پرداخت کمتر است و می‌خواهیم ساعت اوج را هم ببینیم. صفر رخداد. حادثه بسته می‌شود.

از گزارش تا رفع فوری حدود پنجاه دقیقه. بدون trace_id و گروه‌بندی، احتمالاً ساعت‌ها طول می‌کشید تا کسی Warning «expired» را در سرویس orders کنار callback در سرویس payments بگذارد. حالت مشابهی را برای خطاهای ۵۰۰ عمومی‌تر در مقالهٔ خطای ۵۰۰ در پروداکشن بررسی کرده‌ام.

عادت‌هایی که روش را سریع‌تر می‌کنند

هر جستجو را به اشتراک بگذارید، نه عکس صفحه را. لینکی که فیلترها و بازه را در خود دارد، به همکار اجازه می‌دهد همان چیزی را ببیند که شما می‌بینید و ادامه دهد. نحوهٔ ساخت فیلترهای دقیق را در آموزش جستجو و فیلتر لاگ‌ها آورده‌ام.
استقرارها را ثبت کنید. حتی یک لاگ Information با شمارهٔ نسخه در شروع هر سرویس، جواب سؤال «از کِی؟» را چند برابر سریع‌تر می‌کند.
یک خط‌زمانی بنویسید. وسط حادثه، در کانال، هر یافته را با ساعتش بنویسید. بعداً برای گزارش پس از حادثه طلاست، و وسط کار جلوی دوباره‌کاری را می‌گیرد.
مدت نگه‌داری را با واقعیت تنظیم کنید. باگی که هفته‌ای یک بار رخ می‌دهد با لاگ سه‌روزه قابل بررسی نیست. این حساب‌وکتاب را در مقالهٔ مدت نگه‌داری لاگ باز کرده‌ام.
بعد از هر حادثه یک سؤال: کدام گام کند بود و چرا؟ جواب معمولاً یک لاگ کم، یک فیلد ساخت‌نیافته یا یک trace_id پاره‌شده است. همان را درست کنید.

هیچ‌کدام از این گام‌ها به ابزار خاصی وابسته نیست؛ با هر سامانهٔ لاگ متمرکزی که فیلتر و trace_id داشته باشد انجام‌شدنی است. چیزی که فرق می‌گذارد، انضباط است: به ترتیب، بدون پریدن به نتیجه، و با تأیید در آخر.

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

فصل عیب‌یابی مؤثر در کتاب SRE گوگل — روش فرضیه‌محور عیب‌یابی و دام‌های رایجش، از زبان تیمی که در مقیاس بزرگ حادثه مدیریت می‌کند.
انتقال context در OpenTelemetry — اینکه trace_id دقیقاً چطور بین سرویس‌ها منتقل می‌شود و کجا ممکن است پاره شود.
لاگ در ⁦.NET⁩ و ⁦ASP.NET Core⁩ (Microsoft Learn) — مرجع رسمی سطح‌ها، دسته‌ها و scopeها که پایهٔ لاگ قابل‌جستجو در ⁦.NET⁩ است.
راهنمای NIST SP 800-92 دربارهٔ مدیریت لاگ — چارچوب کلاسیک برنامه‌ریزی، نگه‌داری و تحلیل لاگ در سازمان.