یادداشت‌های بک‌اند ۶: لاگ ساخت‌یافته با Serilog در ASP.NET Core

در یادداشت قبلی گفتم محیط عملیاتی ارزش لاگی را به من یاد داد که به سؤال ساعت سه صبح جواب بدهد. این یادداشت دربارهٔ شکل چنین لاگی در یک سرویس ASP.NET Core است،‏ و دربارهٔ تصمیم‌های کوچکی که تعیین می‌کنند لاگ مدرک باشد یا فقط سروصدا.

Serilog را سال ۲۰۲۱ در «گزینه دو» وارد پروژه کردم،‏ وقتی هنوز آن‌جا فول‌استک کار می‌کردم،‏ و بعد از این‌که به نقش ارشد بک‌اند رفتم هم لاگ ساخت‌یافته کنار Docker و CI/CD بخشی از چیدمان استاندارد ماند. هدف کوتاه‌تر کردن مسیر بود: از «یک دانش‌آموز می‌گوید آزمون هنگ کرد» تا درخواستی که شکست خورده،‏ کاربر و آزمونی که به آن تعلق داشته،‏ زمانی که هر مرحله گرفته و استثنایی که کار را تمام کرده. نصب بسته بخش کوچکی از کار بود؛‏ بیشترش توافق بر سر این بود که هر رویداد چه چیزهایی را باید با خودش داشته باشد.

قالب پیام،‏ نه رشته

مهم‌ترین عادت کوچک‌ترینشان هم هست. این دو فراخوانی را مقایسه کنید:

// Interpolated: the values are baked into the text, so every call is a different message
logger.LogWarning($"Answer save took {elapsed.TotalMilliseconds} ms for session {sessionId}");

// Template: one event type with two properties you can query
logger.LogWarning("Answer save took {ElapsedMs} ms for session {SessionId}",
    elapsed.TotalMilliseconds, sessionId);

خط اول یک رشته تولید می‌کند. خط دوم یک رویداد با قالب ثابت و دو پراپرتی نام‌دار می‌سازد،‏ پس انبارهٔ لاگ بدون عبارت باقاعده می‌تواند به سؤال‌هایی مثل «همهٔ ذخیره‌های کندتر از ۵۰۰ میلی‌ثانیه را نشان بده» یا «هشدارها را بر اساس قالب گروه‌بندی کن» جواب بدهد. نسخهٔ درون‌یابی‌شده (string interpolation) رشته‌اش را پیش از آن می‌سازد که لاگر بررسی کند سطح Warning اصلاً فعال است یا نه. تحلیلگرهای .NET این الگو را با قاعدهٔ CA2254 علامت می‌زنند،‏ با این مضمون که قالب باید یک عبارت ثابت باشد،‏ و من در بازبینی کد این هشدار را مثل خطا جدی می‌گیرم.

در دو جا راحت می‌شود اشتباه کرد. در متدهای الحاقی ILogger مثل LogWarning،‏ جای‌نگهدارها بر اساس ترتیب به آرگومان‌ها نسبت داده می‌شوند،‏ نه بر اساس نام؛‏ پس {SessionId} هر چیزی را می‌گیرد که دوم آمده باشد. دیگر این‌که عملگر @،‏ مثل {@Request}،‏ به Serilog می‌گوید کل شیء را سریال‌سازی کند. این راحت است و خطرناک: همهٔ پراپرتی‌های عمومی را لاگ می‌کنید،‏ حتی آن‌هایی که سال بعد اضافه می‌شوند. من ترجیح می‌دهم همان چند پراپرتی لازم را با نام بنویسم.

برای مسیرهای داغ،‏ تولیدکنندهٔ کد [LoggerMessage] همان رویداد ساخت‌یافته را بدون boxing و بدون تجزیهٔ قالب در هر فراخوانی می‌سازد،‏ و با Serilog هم کار می‌کند،‏ چون Serilog پشت همان انتزاع ILogger نشسته است:

public static partial class ExamLog
{
    [LoggerMessage(EventId = 1001, Level = LogLevel.Warning,
        Message = "Answer save took {ElapsedMs} ms for session {SessionId}")]
    public static partial void SlowAnswerSave(ILogger logger, double elapsedMs, Guid sessionId);
}

استثناها جای مخصوص خودشان را دارند و باید از آن استفاده کرد. بنویسید logger.LogError(ex, "Saving answers for session {SessionId} failed", sessionId)،‏ با استثنا به‌عنوان اولین آرگومان. گذاشتن ex.Message در متن پیام،‏ نوع استثنا،‏ stack trace و استثناهای درونی را دور می‌ریزد و هر پیام متفاوت را به یک قالب تازه تبدیل می‌کند. هر استثنا را یک بار لاگ کنید،‏ همان جایی که واقعاً مدیریتش می‌کنید. لاگ کردن و دوباره پرتاب کردن در هر لایه پنج نسخه از یک stack trace می‌سازد و شمارش خطاها دیگر معنایی ندارد.

اتصال Serilog به ASP.NET Core

از راه‌اندازی دومرحله‌ای مستندات Serilog.AspNetCore استفاده می‌کنم. یک لاگر موقت (bootstrap) از خط اول Program.cs وجود دارد تا اگر برنامه هنگام خواندن پیکربندی از کار افتاد،‏ باز هم چیزی ثبت شود،‏ و وقتی host ساخته شد،‏ لاگر اصلی جایش را می‌گیرد:

using Serilog;
using Serilog.Formatting.Compact;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateBootstrapLogger();

try
{
    var builder = WebApplication.CreateBuilder(args);

    builder.Services.AddSerilog((services, lc) => lc
        .ReadFrom.Configuration(builder.Configuration)
        .ReadFrom.Services(services)
        .Enrich.FromLogContext()
        .Enrich.WithProperty("Service", "exam-api")
        .WriteTo.Console(new CompactJsonFormatter()));

    var app = builder.Build();
    app.UseSerilogRequestLogging();
    // ... the rest of the pipeline and the endpoints
    app.Run();
}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush();
}

AddSerilog همهٔ فراخوانی‌های ILogger<T> را،‏ چه در کد برنامه و چه در خود فریم‌ورک،‏ از مسیر Serilog عبور می‌دهد،‏ پس کد موجود تغییری نمی‌کند. حداقل سطح‌ها در پیکربندی تعریف می‌شوند و بنابراین بدون build دوباره می‌توانند در هر محیط متفاوت باشند:

"Serilog": {
  "MinimumLevel": {
    "Default": "Information",
    "Override": {
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.EntityFrameworkCore": "Warning",
      "System.Net.Http.HttpClient": "Warning"
    }
  }
}

یک رویداد برای هر درخواست،‏ و زمینه روی همهٔ رویدادها

ASP.NET Core به‌طور پیش‌فرض برای هر درخواست چند رویداد Information می‌نویسد. UseSerilogRequestLogging() آن‌ها را با یک رویداد پایانی جایگزین می‌کند که متد،‏ مسیر،‏ کد وضعیت و زمان سپری‌شده را در خود دارد؛‏ به همین دلیل پیکربندی بالا سطح Microsoft.AspNetCore را تا Warning پایین می‌آورد. همین یک رویداد ستون فقرات بیشتر بررسی‌هاست و ارزش دارد غنی‌اش کنیم:

app.UseSerilogRequestLogging(options =>
{
    options.GetLevel = (http, elapsedMs, ex) =>
        ex is not null || http.Response.StatusCode >= 500 ? LogEventLevel.Error
        : http.Request.Path.StartsWithSegments("/health") ? LogEventLevel.Verbose
        : elapsedMs > 1000 ? LogEventLevel.Warning
        : LogEventLevel.Information;
});

app.UseAuthentication();

// after authentication, so the user and tenant are known
app.Use(async (http, next) =>
{
    var userId = http.User.FindFirst("sub")?.Value;
    var tenantId = http.User.FindFirst("tenant_id")?.Value;

    var diagnostics = http.RequestServices.GetRequiredService<IDiagnosticContext>();
    diagnostics.Set("UserId", userId);          // for the completion event
    diagnostics.Set("TenantId", tenantId);

    using (LogContext.PushProperty("UserId", userId))     // for every event inside the request
    using (LogContext.PushProperty("TenantId", tenantId))
    {
        await next(http);
    }
});

این دو سازوکار تکراری به نظر می‌رسند،‏ ولی نیستند. LogContext.PushProperty پراپرتی را به همهٔ رویدادهایی می‌چسباند که داخل بلوک using نوشته می‌شوند،‏ اما میان‌افزار لاگ درخواست رویداد پایانی‌اش را بعد از تمام شدن همین بلوک می‌نویسد. IDiagnosticContext دقیقاً برای همان رویداد وجود دارد. با داشتن هر دو،‏ همهٔ خط‌های یک درخواست،‏ از جمله خلاصهٔ پایانی،‏ بر اساس کاربر و مستأجر (tenant) قابل فیلترند.

نام claimها به سرویس هویت شما بستگی دارد. قاعده‌ای که به آن پایبندم این است که این‌ها شناسه‌اند،‏ نه آدم‌ها: یک شناسهٔ کاربری مات و بی‌معنا،‏ هرگز شمارهٔ تلفن یا نام. در پلتفرم چندمستأجری‌ای که در حال ساختنش هستم،‏ شناسهٔ مستأجر برای هر درخواست یک بار تعیین می‌شود و در لاگ‌ها و traceها مجاز است،‏ اما نه به‌عنوان برچسب متریک،‏ چون آن‌جا تعداد سری‌های زمانی را در تعداد مستأجرها ضرب می‌کند.

سطح‌ها فقط وقتی معنا دارند که تیم بر سرشان توافق کند

تعریف‌هایی که در بازبینی رویشان پافشاری می‌کنم کوتاه‌اند. Error یعنی کسی باید این را ببیند. Warning یعنی چیزی افت کرد ولی مدیریت شد: یک تلاش دوباره موفق شد،‏ از راه جایگزین استفاده شد،‏ یا درخواستی کند بود. Information رویدادهای کسب‌وکاری و همان یک خلاصه برای هر درخواست را ثبت می‌کند. Debug و Verbose در محیط عملیاتی خاموش‌اند و هر وقت بررسی‌ای لازمشان داشت،‏ از طریق پیکربندی و هر بار فقط برای یک namespace روشن می‌شوند. اگر حتی تغییر پیکربندی هم کند باشد،‏ یک LoggingLevelSwitch که به MinimumLevel.ControlledBy(...) داده شده،‏ از یک اندپوینت مدیریتی احراز هویت‌شده در زمان اجرا قابل تغییر است و بعد از پایان بررسی برمی‌گردد.

نمونه‌برداری همان جایی است که آدم‌ها یا بیش از حد خرج می‌کنند یا مدرک از دست می‌دهند. من از خطاها نمونه‌برداری نمی‌کنم،‏ و از خلاصهٔ درخواست‌های کاربران واقعی هم نه،‏ چون بررسی‌ها از همین رویدادها شروع می‌شوند. چیزی که حذف می‌کنم سروصدای شناخته‌شده است: بررسی‌های سلامت (قاعدهٔ GetLevel بالا آن‌ها را به Verbose،‏ زیر حداقل سطح،‏ می‌فرستد)،‏ probeهای آمادگی و دسته‌های پرحرف فریم‌ورک. وقتی فیلتر باید دقیق‌تر باشد،‏ Serilog.Expressions اجازه می‌دهد آن را به‌صورت متن بنویسید،‏ مثلاً Filter.ByExcluding("RequestPath like '/health%'"). نمونه‌برداری آماری جایش در traceهاست،‏ جایی که ابزارهای OpenTelemetry برای همین کار ساخته شده‌اند.

مقصدها: رویدادها کجا می‌روند

در کانتینرها JSON فشرده را روی خروجی استاندارد می‌نویسم و جمع‌آوری‌اش را به پلتفرم می‌سپارم. برنامه از سامانهٔ ذخیرهٔ لاگ بی‌خبر می‌ماند و عوض کردن آن یک تصمیم عملیاتی است. برای یک تیم کوچک،‏ Seq جای خوبی برای خواندن رویدادهای ساخت‌یافته است،‏ هم در توسعه و هم در محیط‌های عملیاتی متوسط؛‏ sink آن رویدادها را دسته‌ای می‌فرستد،‏ پس شبکهٔ کند درخواست‌ها را کند نمی‌کند.

یک جدول SQL می‌تواند خانهٔ معقولی فقط برای خطاها باشد،‏ به‌خصوص وقتی تیم همین حالا با SQL Server کار می‌کند و ابزار دیگری ندارد. یک sink جداگانه با حداقل سطح،‏ حجم را کوچک نگه می‌دارد:

.WriteTo.Console(new CompactJsonFormatter())
.WriteTo.MSSqlServer(
    connectionString: builder.Configuration.GetConnectionString("Logs"),
    sinkOptions: new MSSqlServerSinkOptions { TableName = "ErrorLog", AutoCreateSqlTable = true },
    restrictedToMinimumLevel: LogEventLevel.Error)

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

ربط دادن لاگ‌ها به traceها

لاگ‌ها می‌گویند درون یک پروسه چه گذشت؛‏ traceها نشان می‌دهند یک درخواست چطور بین پروسه‌ها حرکت کرد. وقتی شناسهٔ مشترک داشته باشند،‏ خیلی مفیدتر می‌شوند. از Serilog 3.1 به بعد،‏ هر رویداد شناسهٔ trace و span مربوط به Activity.Current را خودکار برمی‌دارد و فرمت‌کنندهٔ JSON فشرده آن‌ها را با نام‌های @tr و @sp می‌نویسد. ردگیری OpenTelemetry را روشن کنید تا این شناسه‌ها شناسه‌های واقعی W3C باشند و با هر سرویسی که درخواست از آن عبور می‌کند مشترک شوند:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(r => r.AddService("exam-api"))
    .WithTracing(t => t
        .AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddOtlpExporter());

این حلقه‌ای را می‌بندد که در یادداشت Minimal APIs باز شد. traceIdای که تنظیمات ProblemDetails در هر پاسخ خطا می‌گذارد،‏ همان شناسه‌ای است که روی همهٔ رویدادهای لاگ آن درخواست نشسته. کاربر یا همکار پشتیبانی متن خطا را برایتان می‌فرستد؛‏ شناسهٔ trace را در جست‌وجوی لاگ می‌گذارید و کل درخواست را در همهٔ سرویس‌ها می‌بینید. اگر می‌خواهید لاگ‌ها هم از طریق OTLP منتقل شوند،‏ Serilog.Sinks.OpenTelemetry آن‌ها را به همان collectorی می‌فرستد که traceها به آن می‌روند.

دادهٔ شخصی و اطلاعات محرمانه

لاگ‌ها گسترده‌تر از پایگاه‌داده کپی می‌شوند و با دقت کمتری نگهداری می‌شوند،‏ پس با آن‌ها مثل جایی رفتار می‌کنم که دادهٔ حساس هرگز نباید به آن برسد. فهرستی که در بازبینی بررسی می‌کنم:

• هرگز رمز عبور،‏ توکن،‏ هدرهای Authorization یا Cookie،‏ رشتهٔ اتصال،‏ کلید API یا کد یک‌بارمصرف را لاگ نکنید.
• پرهیز کنید از شمارهٔ تلفن،‏ نشانی ایمیل،‏ کد ملی و نام کامل. شناسهٔ داخلی را لاگ کنید و هر وقت لازم شد،‏ با همان کنترل‌های دسترسی پایگاه‌داده،‏ فرد را پیدا کنید.
• به‌طور پیش‌فرض بدنهٔ کامل درخواست یا پاسخ را لاگ نکنید. اگر برای بررسی مشخصی به بدنه نیاز بود،‏ شکل خلاصه‌شده‌اش را برای مدت محدود لاگ کنید.
• EnableSensitiveDataLogging() در EF Core را فقط برای محیط توسعه نگه دارید؛‏ این گزینه مقدار پارامترهای SQL را وارد لاگ‌ها می‌کند.
• سریال‌سازی آگاهانه. اگر نوعی باید لاگ شود،‏ Destructure.ByTransforming<T>(...) یک بار برای همیشه تعیین می‌کند کدام فیلدها امن‌اند.

مدت نگهداری هم بخشی از همین تصمیم است. لاگ‌های جزئی را تا وقتی نگه دارید که واقعاً با آن‌ها بررسی می‌کنید،‏ نه بیشتر.

لاگ چقدر هزینه دارد

لاگ صورت‌حساب دارد: پردازنده و تخصیص حافظه در پروسه،‏ شبکه،‏ فضای ذخیره‌سازی،‏ ایندکس‌گذاری و زمانی که آدم‌ها صرف خواندن می‌کنند. وقتی ده‌ها هزار دانش‌آموز هم‌زمان فعال‌اند،‏ حتی یک رویداد Information برای هر درخواست هم دادهٔ زیادی است،‏ و یک LogInformation داخل یک حلقه می‌تواند از همه‌چیز سنگین‌تر شود. هر چند وقت یک بار رویدادها را بر اساس قالب می‌شمارم،‏ کاری که با لاگ ساخت‌یافته ساده است،‏ و ده قالب اول را نگاه می‌کنم. یافته‌های معمول این‌هاست: یک دستهٔ فریم‌ورک که روی Information مانده،‏ یک خط debug که به یک حلقهٔ داغ راه پیدا کرده،‏ و یک شیء بزرگ که در هر فراخوانی سریال‌سازی می‌شود. درست کردن همین سه مورد معمولاً از هر طرح نمونه‌برداری مؤثرتر است.

اگر لاگ‌هایتان پرسروصدا به نظر می‌رسند و باز هم هنگام حادثه به سؤال‌هایتان جواب نمی‌دهند،‏ این از جنس کارهای بک‌اند است که انجام می‌دهم. یادداشت بعدی از آنچه سرویس گزارش می‌دهد به چیزی می‌رسد که هرگز نباید قاطی کند: مستأجرها در یک پایگاه‌دادهٔ مشترک PostgreSQL،‏ با محافظت فیلترهای EF Core و امنیت سطح سطر.

این یادداشت به انگلیسی هم منتشر شده است: نسخهٔ انگلیسی.