Logování a health checks v ASP.NET Core v produkci

Aplikace v ASP.NET Core v produkci od tebe potřebuje dvě věci, dřív než cokoli chytrého: logy, které říkají, co se stalo, na úrovni, kterou sis zvolil záměrně, a endpoint, který říká, jestli aplikace právě teď zvládne svou práci. Vestavěný ILogger pokryje to první, pokud nastavíš Logging:LogLevel promyšleně a budeš psát strukturované zprávy místo interpolovaných řetězců. AddHealthChecks() spolu s MapHealthChecks("/healthz") pokryje to druhé na dvou řádcích. Serilog stojí za přidání, když chceš soubory, obohacování událostí nebo logovací server; k dobrému logování ho nepotřebuješ. Tento příspěvek projde obě poloviny v pořadí, v jakém na ně narazíš, s výchozími hodnotami, konfiguračními klíči a chybami, které z logování udělají incident s plným diskem.

Jak funguje logování v ASP.NET Core#

Logování je součást generického hostu. Když zavoláš WebApplication.CreateBuilder(args), builder zaregistruje providery pro konzoli, debug a event source (ve Windows i protokol událostí Windows) a přečte sekci Logging v konfiguraci. Cokoli, co si přes dependency injection vyžádá ILogger<T>, dostane logger, jehož kategorie je celý název T, a každé volání logu se filtruje podle této kategorie, než se dostane k provideru.

public class OrderService(ILogger<OrderService> logger, AppDbContext db){    public async Task PlaceAsync(Order order)    {        db.Orders.Add(order);        await db.SaveChangesAsync();        logger.LogInformation("Order {OrderId} placed for {CustomerId}",            order.Id, order.CustomerId);    }}

Kategorie je důležitá, protože se podle ní filtr páruje. Microsoft.EntityFrameworkCore.Database.Command je kategorie, která loguje každý příkaz SQL, Microsoft.AspNetCore.Hosting.Diagnostics loguje začátek a konec požadavku a MyApp.OrderService je ta z příkladu výše. Filtry se párují podle předpony, takže pravidlo pro Microsoft.AspNetCore pokrývá všechno pod ním.

Úrovní je sedm a tvoří uspořádanou škálu, ne sadu štítků:

Filtr nastavený na Warning pustí Warning, Error a Critical a zbytek zahodí. Cena zahozené zprávy je velmi malá - logger zkontroluje úroveň dřív, než cokoli naformátuje - a proto můžeš volání LogDebug nechat v kódu, aniž by tě stálo výkon.

Nastavení úrovní logů v appsettings a proměnných prostředí#

appsettings.json ze šablony je pro produkci skoro správně:

{  "Logging": {    "LogLevel": {      "Default": "Information",      "Microsoft.AspNetCore": "Warning",      "Microsoft.EntityFrameworkCore.Database.Command": "Warning"    }  }}

Default platí pro každou kategorii bez konkrétnějšího pravidla. Microsoft.AspNetCore na Warning umlčí průběžné klábosení frameworku, které jinak vytváří dva a více řádků na každý požadavek, včetně každého statického souboru. Řádek pro Entity Framework je ten, na který lidé zapomínají: na Information EF Core loguje každý provedený příkaz SQL s jeho dobou trvání, což je užitečné na notebooku a pod zátěží záplava.

Konfigurace je vrstvená, takže úroveň na běžícím nasazení jen zřídka potřebuješ měnit úpravou souboru. Proměnné prostředí přebíjejí JSON a oddělovač vnořených klíčů je dvojité podtržítko:

Logging__LogLevel__Default=WarningLogging__LogLevel__Microsoft.EntityFrameworkCore.Database.Command=Information

Název kategorie s tečkami funguje jako klíč proměnné prostředí v Linuxu. appsettings.Production.json se načte nad appsettings.json, když je ASPNETCORE_ENVIRONMENT (nebo DOTNET_ENVIRONMENT) nastavená na Production, což je také výchozí hodnota, pokud není nastavená ani jedna. Celé pořadí vrstvení vysvětlují konfigurace a tajemství v ASP.NET Core a vyplatí se to přečíst dřív, než connection string někam dáš.

Změny appsettings.json na disku se za běhu aplikace projeví, protože výchozí zdroj JSON má nastavené reloadOnChange. Proměnné prostředí se čtou jednou při startu, takže jejich změna znamená restart.

Psaní zpráv do logu, které stojí za přečtení#

Nejčastější chyba v logování v .NET je interpolace řetězců:

// Špatně: formátuje se pokaždé a hodnoty se ztratí jako polelogger.LogInformation($"Order {order.Id} placed for {order.CustomerId}");// Správně: šablona zprávy s pojmenovanými zástupnými symbolylogger.LogInformation("Order {OrderId} placed for {CustomerId}",    order.Id, order.CustomerId);

Druhý tvar je šablona zprávy. Zástupné symboly se k argumentům párují podle pozice, ne podle jména, a jména se stanou vlastnostmi události logu. S obyčejným konzolovým loggerem vidíš v obou případech stejnou větu. Se strukturovaným providerem - JSON formátovačem konzole, Serilogem nebo čímkoli, co posílá logy na logovací server - dostaneš OrderId a CustomerId jako pole, podle kterých můžeš filtrovat, a samotná šablona zůstává konstantní, takže „kolikrát se tahle zpráva stala“ je jednoduché spočítání. Interpolovaná verze se navíc formátuje i tehdy, když je úroveň odfiltrovaná, protože řetězec se sestaví dřív, než se metoda zavolá.

Pro horké cesty odstraní zbylou cenu atribut LoggerMessage generovaný zdrojovým kódem: žádný boxing hodnotových typů, žádné parsování šablony za běhu a kontrola úrovně dřív, než se cokoli vyhodnotí.

public static partial class Log{    [LoggerMessage(Level = LogLevel.Warning,        Message = "Payment provider slow: {ElapsedMs} ms for order {OrderId}")]    public static partial void PaymentSlow(ILogger logger, long elapsedMs, int orderId);}

Tři návyky stojí za víc než jakákoli volba provideru:

• Loguj výjimky jako výjimky. logger.LogError(ex, "Charging order {OrderId} failed", id) uchová stack trace jako strukturované pole. Dát ex.Message do šablony zahodí část, kterou potřebuješ.
• Jeden řádek na událost, ne na krok. Požadavek, který na šťastné cestě zaloguje deset řádků Information, pohřbí jedno Warning, na kterém záleží.
• Nikdy neloguj tajemství ani celá těla požadavků. Hesla, tokeny, connection stringy a čísla karet skončí v souborech logů, které se kopírují, stahují a uchovávají mnohem déle než data, která popisují.

Scopes připojují kontext ke každé zprávě zapsané uvnitř nich, což je způsob, jak dostat číslo objednávky na řádky logované kódem, který o objednávkách neví. Dělá to using (logger.BeginScope("Order {OrderId}", id)) { ... }; provider konzole zobrazuje scopes jen tehdy, když je u jeho formátovače zapnuté IncludeScopes, zatímco strukturované providery je zaznamenají jako vlastnosti.

Výstup na konzoli v kontejneru#

Na hostiteli s kontejnery je konzole logem. Co proces zapíše na standardní výstup, to ti panel ukáže, a co se mezi restarty uchová, závisí na hostiteli, takže konzoli ber jako živý pohled, ne jako archiv. Výchozí jednoduchý formátovač zapisuje dva řádky na zprávu (na jednom kategorii, na dalším text), což se v živé konzoli čte špatně. Pomůžou dvě změny:

builder.Logging.ClearProviders();builder.Logging.AddSimpleConsole(options =>{    options.SingleLine = true;    options.TimestampFormat = "yyyy-MM-dd HH:mm:ss ";    options.UseUtcTimestamp = true;});

Pokud tvoje logy zpracovává něco dál po proudu, použij místo toho builder.Logging.AddJsonConsole(), který zapisuje jeden objekt JSON na řádek se šablonou, vyrenderovanou zprávou a každou pojmenovanou vlastností.

Na RE:NODE ukazuje záložka konzole výstup procesu nefiltrovaně a živě, vedle grafů paměti, CPU a disku proti limitům tarifu, takže jednořádková konzole s časovými značkami je to, co budeš skutečně číst, když se něco pokazí. Není to archiv logů: pokud potřebuješ chyby z minulého úterý o měsíc později, zapisuj je někam, kde se uchovají.

Serilog: kdy stojí za přidání#

Serilog si své místo zaslouží, když chceš jednu ze tří věcí, které vestavěné providery nedělají dobře: rotující soubory logů s retencí, obohacování (název stroje, ID požadavku, ID uživatele u každé události) nebo odesílání na logovací server jako Seq, Elasticsearch nebo Grafana Loki přes sink. Nastavení je balíček a pár řádků:

$ dotnet add package Serilog.AspNetCore$ dotnet add package Serilog.Sinks.File

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());    var app = builder.Build();    app.UseSerilogRequestLogging();    // ... endpoints    app.Run();}catch (Exception ex){    Log.Fatal(ex, "Host terminated unexpectedly");}finally{    Log.CloseAndFlush();}

Bootstrap logger zachytí selhání při startu, před načtením konfigurace - což je přesně chvíle, kdy chybějící proměnná prostředí shodí aplikaci a výchozí nastavení vypíše velmi málo. Log.CloseAndFlush() je důležité pro asynchronní a dávkové sinky: bez něj jsou poslední zprávy před pádem při ukončení procesu pořád v bufferu.

UseSerilogRequestLogging() nahradí několik řádků frameworku na požadavek jedním řádkem s metodou, cestou, stavovým kódem a uplynulým časem, což je log požadavků, který většina lidí skutečně chce. Zkombinuj ho s přepisem Microsoft.AspNetCore na Warning, aby se vlastní řádky frameworku nezapisovaly také.

Konfigurace žije ve vlastní sekci, která nahradí Logging, jakmile Serilog převezme řízení:

{  "Serilog": {    "MinimumLevel": {      "Default": "Information",      "Override": {        "Microsoft.AspNetCore": "Warning",        "Microsoft.EntityFrameworkCore": "Warning"      }    },    "WriteTo": [      { "Name": "Console" },      {        "Name": "File",        "Args": {          "path": "logs/app-.log",          "rollingInterval": "Day",          "retainedFileCountLimit": 14,          "fileSizeLimitBytes": 52428800,          "rollOnFileSizeLimit": true        }      }    ]  }}

Pokud soubory nepotřebuješ, nezapisuj je. Aplikace jen s konzolí, která posílá logy na logovací server přes sink, nemá čím disk zaplnit. Co uchovávat a jak dlouho, rozebírají logy, které stojí za uchování.

Health checks: liveness, readiness a závislosti#

Health check endpoint odpovídá stroji na jednu otázku: zvládne tato instance právě teď obsluhovat požadavky? ASP.NET Core dodává potřebnou infrastrukturu v balení.

builder.Services.AddHealthChecks()    .AddCheck("self", () => HealthCheckResult.Healthy(), tags: ["live"])    .AddDbContextCheck<AppDbContext>(tags: ["ready"]);var app = builder.Build();app.MapHealthChecks("/healthz/live", new HealthCheckOptions{    Predicate = check => check.Tags.Contains("live")});app.MapHealthChecks("/healthz/ready", new HealthCheckOptions{    Predicate = check => check.Tags.Contains("ready")});

AddDbContextCheck pochází z balíčku Microsoft.Extensions.Diagnostics.HealthChecks.EntityFrameworkCore a prostě se EF Core zeptá, jestli se umí připojit. Pro kontroly databáze bez EF Core nabízejí komunitní balíčky AspNetCore.HealthChecks.* metody AddSqlServer, AddNpgSql, AddMySql, AddRedis a mnoho dalších; jsou hojně používané, ale nejsou součástí frameworku, takže jejich verze fixuj jako každou jinou závislost.

Odpověď je prostý text - Healthy, Degraded nebo Unhealthy - s kódy stavu mapovanými ve výchozím stavu takto:

Rozdělení na liveness a readiness je ta část, která výpadkům předchází, místo aby je způsobovala. Liveness se ptá „žije proces a není zaseknutý“ a neměla by kontrolovat nic externího. Readiness se ptá „zvládne obsluhovat skutečné požadavky“ a sem patří databáze. Pokud tvůj jediný endpoint kontroluje databázi a něco aplikaci restartuje pokaždé, když tento endpoint selže, pětivteřinový výkyv databáze restartuje všechny instance najednou a všechny se znovu připojí zároveň. Liveness kontrola, která se nedotkne žádné závislosti, to způsobit nemůže.

Vlastní kontrola je třída implementující IHealthCheck:

public class QueueDepthCheck(IJobQueue queue) : IHealthCheck{    public async Task<HealthCheckResult> CheckHealthAsync(        HealthCheckContext context, CancellationToken cancellationToken = default)    {        var depth = await queue.CountAsync(cancellationToken);        return depth switch        {            < 1_000 => HealthCheckResult.Healthy($"{depth} jobs queued"),            < 10_000 => HealthCheckResult.Degraded($"{depth} jobs queued"),            _ => HealthCheckResult.Unhealthy($"{depth} jobs queued")        };    }}builder.Services.AddHealthChecks()    .AddCheck<QueueDepthCheck>("queue", timeout: TimeSpan.FromSeconds(3), tags: ["ready"]);

Dej timeout každé kontrole, která sahá na síť. Health endpoint, který se zasekne na třicet sekund, je horší než ten, který vrátí 503, protože to, co se na něj dotazuje, může držet spojení otevřená a hromadit je.

Zabezpečení a zveřejnění health endpointu#

Výchozí odpověď je jediné slovo, které je bezpečné zveřejnit. V okamžiku, kdy přidáš podrobný writer - oblíbený UIResponseWriter.WriteHealthCheckUIResponse z AspNetCore.HealthChecks.UI.Client nebo vlastní JSON s popisem a výjimkou každé kontroly - zveřejňuješ názvy svých závislostí a někdy i jejich chybové zprávy. Veřejný endpoint drž stručný a podrobný dej za autorizaci nebo omezení hostitele:

app.MapHealthChecks("/healthz/ready");                 // public, one wordapp.MapHealthChecks("/healthz/detail", new HealthCheckOptions{    ResponseWriter = UIResponseWriter.WriteHealthCheckUIResponse}).RequireAuthorization("Ops");

Health endpointy vyluč z logování požadavků, jinak monitor, který se dotazuje každých třicet sekund, zapíše skoro tři tisíce řádků denně o ničem. U Serilogu je může volba GetLevel v UseSerilogRequestLogging shodit na Verbose.

Věz, co endpoint skutečně volá. Na RE:NODE hlídač pádů platformy kontroluje každé dvě minuty server, jehož uptime se vrátil dozadu nebo který přešel offline, a po třech neočekávaných restartech za hodinu otevře tiket. Sleduje proces; tvůj /healthz nevolá. Zaseknutou aplikaci, jejíž proces pořád žije a vrací 503, nerestartuje, takže na URL pro readiness přes svou doménu namiř externí monitor dostupnosti. Na co upozorňovat, pokrývá monitoring, který ti něco řekne, a druhou polovinu - přepnutí readiness na unhealthy, když se aplikace zastavuje, aby jí proxy přestala posílat provoz dřív, než skončí - řádné ukončení a health checks.

Logování požadavků, HTTP logging a korelace#

Existují tři nástroje na úrovni požadavků a nejsou zaměnitelné:

• Logování požadavků v Serilogu - jeden souhrnný řádek na požadavek. Správná výchozí volba.
• `AddHttpLogging` / `UseHttpLogging` - middleware frameworku pro HTTP logging, který umí zahrnout hlavičky a těla. Loguje na úrovni Information v kategorii Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware, takže nic neukáže, dokud filtr tuto kategorii nepropustí. Užitečný pro krátké ladění; nebezpečný, když zůstane zapnutý, protože hlavičky obsahují cookies a autorizační tokeny, pokud neomezíš RequestHeaders a ResponseHeaders.
• `AddW3CLogging` - přístupový log ve formátu W3C extended, zapisovaný do souborů. Šikovný, pokud už máš nástroje, které čtou logy ve stylu IIS.

Pro korelaci má každý požadavek už HttpContext.TraceIdentifier a s výchozím sledováním Activity nese každá událost logu uvnitř požadavku TraceId a SpanId, pokud je provider zaznamenává (umí to JSON formátovač konzole i Serilog). Vracej trace ID v chybových odpovědích - ProblemDetails obsahuje rozšíření traceId ve výchozím stavu, když použiješ AddProblemDetails() - a snímek obrazovky s chybovou stránkou od uživatele se promění v přímé hledání v tvých lozích.

Za reverzní proxy je adresa klienta v lozích požadavků adresou proxy, dokud nezapneš forwarded headers. Skutečná IP klienta přichází v X-Forwarded-For a ASP.NET Core za reverzní proxy ukazuje ForwardedHeadersOptions, které nastaví HttpContext.Connection.RemoteIpAddress správně, což čtou jak tvoje logy, tak každý rate limiter.

Řešení potíží#

Neloguje se vůbec nic. Obvykle se zavolalo ClearProviders() a nic se nepřidalo zpět, nebo byl nakonfigurovaný Serilog, ale jeho sekce WriteTo je prázdná nebo s překlepem. SelfLog.Enable(Console.Error) v Serilogu vypíše jeho vlastní chyby konfigurace.

Konzole je zaplavená SQL. Microsoft.EntityFrameworkCore.Database.Command je na Information, buď výslovně, nebo přes Default. Přidej přepis na Warning.

Start spadne bez použitelného výstupu. Výjimka nastala dřív, než se logování nakonfigurovalo. Použij bootstrap logger (Serilog) nebo obal builder.Build() a app.Run() do try/catch, který píše do Console.Error, a čti konzoli od začátku.

Health endpoint vrací 503, ale aplikace funguje. Jedna kontrola s tagem pro tento endpoint selhává nebo vyprší. Dočasně namapuj podrobný writer za autorizaci a přečti si, která to je; obvykle jde o závislost, kterou endpoint kontrolovat neměl.

Disk se zaplnil. Najdi nejdřív adresář s logy. Rotující souborové sinky s výchozí retencí, zapomenuté Debug a HTTP logging s těly jsou tři obvyklé příčiny, v tomto pořadí.

Řádky logu ukazují u všech klientů adresu proxy. Forwarded headers nejsou nakonfigurované, nebo KnownProxies neobsahuje adresu proxy, takže middleware hlavičku ignoruje.

FAQ#

Potřebuju Serilog, nebo stačí vestavěné logování?

Vestavěný ILogger s JSON formátovačem konzole stačí aplikaci, jejíž logy se čtou z konzole nebo sbírají ze standardního výstupu. Serilog stojí za přidání kvůli rotujícím souborům s retencí, obohacování každé události nebo sinku na logovací server. Tvůj kód volá ILogger tak či tak, takže pozdější přechod stojí jednu změnu nastavení.

Na jaké úrovni má běžet produkce?

Information pro tvoje vlastní kategorie, Warning pro Microsoft.AspNetCore a EF Core. Když honíš problém, dočasně zvyš jednu kategorii na Debug přes proměnnou prostředí a pak ji vrať zpět.

Má health check testovat databázi?

Kontrola readiness ano, protože aplikace, která se nedostane k databázi, neobslouží většinu požadavků. Kontrola liveness ne, protože restart aplikace databázi neopraví a restart všech instancí najednou zpomalí zotavení.

Proč mi ve výstupu chybí strukturované vlastnosti?

Buď byla zpráva sestavena interpolací řetězce, takže není co zachytit, nebo je provider obyčejný jednoduchý formátovač konzole, který větu vykreslí a pole zahodí. Použij šablonu zprávy a strukturovaný formátovač nebo sink.

Jak často má monitor volat health endpoint?

Pro malou aplikaci stačí každých 30 až 60 sekund. Častěji přidává zátěž a šum v lozích, aniž by ti to řeklo něco o moc dřív, a upozornění až po dvou po sobě jdoucích selháních ti ušetří budíček kvůli jediné pomalé odpovědi.