Логирование и health checks в ASP.NET Core в продакшене

Приложению на ASP.NET Core в продакшене прежде всяких хитростей нужны от вас две вещи: логи, которые сообщают, что произошло, на уровне, выбранном осознанно, и эндпоинт, который говорит, может ли приложение прямо сейчас выполнять свою работу. Встроенный ILogger закрывает первое, если вы продуманно задали Logging:LogLevel и пишете структурированные сообщения вместо интерполированных строк. AddHealthChecks() плюс MapHealthChecks("/healthz") закрывают второе в две строки. Serilog стоит добавлять, когда нужны файлы, обогащение событий или сервер логов; для хорошего логирования он не обязателен. Эта статья проходит обе половины в том порядке, в котором вы с ними столкнётесь, - с настройками по умолчанию, ключами конфигурации и ошибками, которые превращают логирование в инцидент с переполненным диском.

Как устроено логирование в ASP.NET Core#

Логирование - часть generic host. Когда вы вызываете WebApplication.CreateBuilder(args), builder регистрирует провайдеры console, debug и event source (плюс журнал событий Windows на Windows) и читает секцию Logging из конфигурации. Всё, что запрашивает ILogger<T> через внедрение зависимостей, получает логгер, категория которого - полное имя T, и каждый вызов логирования фильтруется по этой категории, прежде чем дойти до провайдера.

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);    }}

Категория важна, потому что именно с ней сопоставляется фильтр. Microsoft.EntityFrameworkCore.Database.Command - категория, которая логирует каждый SQL-запрос, Microsoft.AspNetCore.Hosting.Diagnostics логирует начало и конец запроса, а MyApp.OrderService - та, что в примере выше. Фильтры сопоставляются по префиксу, так что правило для Microsoft.AspNetCore распространяется на всё, что под ним.

Уровней семь, и это упорядоченная шкала, а не набор ярлыков:

Фильтр на Warning пропускает Warning, Error и Critical и отбрасывает остальное. Отброшенное сообщение стоит очень мало - логгер проверяет уровень до какого-либо форматирования, - поэтому вызовы LogDebug можно оставлять в коде, не платя за них.

Уровни логов в appsettings и переменных окружения#

appsettings.json из шаблона почти подходит для продакшена:

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

Default применяется к каждой категории, для которой нет более конкретного правила. Microsoft.AspNetCore на Warning глушит болтовню фреймворка по каждому запросу, которая иначе даёт две и больше строки на каждый запрос, включая каждый статический файл. Строку про Entity Framework обычно забывают: на Information EF Core логирует каждую выполненную SQL-команду с её длительностью, что полезно на ноутбуке и превращается в поток под нагрузкой.

Конфигурация многослойная, поэтому, чтобы поменять уровень на работающем деплое, файл редактировать почти никогда не нужно. Переменные окружения переопределяют JSON, а разделитель вложенных ключей - двойное подчёркивание:

Logging__LogLevel__Default=WarningLogging__LogLevel__Microsoft.EntityFrameworkCore.Database.Command=Information

Имя категории с точками работает как ключ переменной окружения в Linux. appsettings.Production.json загружается поверх appsettings.json, когда ASPNETCORE_ENVIRONMENT (или DOTNET_ENVIRONMENT) равно Production, и это же значение по умолчанию, если ни одна не задана. Конфигурация и секреты в ASP.NET Core объясняет весь порядок слоёв, и её стоит прочитать, прежде чем куда-либо класть строку подключения.

Изменения appsettings.json на диске подхватываются на ходу, потому что у источника JSON по умолчанию включён reloadOnChange. Переменные окружения читаются один раз при запуске, так что изменение любой из них означает перезапуск.

Сообщения, которые стоит читать#

Самая частая ошибка логирования в .NET - интерполяция строк:

// Wrong: formatted every time, and the values are lost as fieldslogger.LogInformation($"Order {order.Id} placed for {order.CustomerId}");// Right: a message template with named placeholderslogger.LogInformation("Order {OrderId} placed for {CustomerId}",    order.Id, order.CustomerId);

Вторая форма - шаблон сообщения. Плейсхолдеры сопоставляются с аргументами по позиции, а не по имени, а имена становятся свойствами события лога. С обычным консольным логгером в обоих случаях вы видите одно и то же предложение. Со структурированным провайдером - JSON-форматтером консоли, Serilog или чем угодно, что отправляет логи на сервер, - вы получаете OrderId и CustomerId как поля, по которым можно фильтровать, а сам шаблон остаётся неизменным, так что вопрос «сколько раз было это сообщение» сводится к простому подсчёту. Интерполированный вариант к тому же форматируется, даже когда уровень отфильтрован, потому что строка собирается до вызова метода.

Для горячих путей атрибут LoggerMessage с генерацией кода убирает оставшиеся издержки: никакой упаковки значимых типов, никакого разбора шаблона во время выполнения и проверка уровня до того, как что-либо вычисляется.

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);}

Три привычки ценнее любого выбора провайдера:

• Логируйте исключения как исключения. logger.LogError(ex, "Charging order {OrderId} failed", id) сохраняет stack trace как структурированное поле. Если поместить ex.Message в шаблон, вы выбросите как раз ту часть, которая нужна.
• Одна строка на событие, а не на шаг. Запрос, который на удачном пути пишет десять строк Information, похоронит под ними тот единственный Warning, который важен.
• Никогда не логируйте секреты и целые тела запросов. Пароли, токены, строки подключения и номера карт оказываются в лог-файлах, которые копируют, скачивают и хранят гораздо дольше, чем данные, которые они описывают.

Scopes прикрепляют контекст к каждому сообщению, записанному внутри них, - так номер заказа попадает в строки, которые пишет код, ничего о заказах не знающий. Это делает using (logger.BeginScope("Order {OrderId}", id)) { ... }; консольный провайдер показывает scopes, только если в его форматтере включён IncludeScopes, а структурированные провайдеры записывают их как свойства.

Вывод в консоль в контейнере#

На контейнерном хостинге консоль и есть лог. Всё, что процесс пишет в стандартный вывод, - это то, что показывает панель, а что сохраняется между перезапусками, зависит от хостинга, поэтому относитесь к консоли как к живому просмотру, а не к архиву. Простой форматтер по умолчанию пишет две строки на сообщение (категорию на одной, текст на следующей), что плохо читается в живой консоли. Помогают два изменения:

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

Если ваши логи дальше кто-то разбирает, используйте вместо этого builder.Logging.AddJsonConsole(), который пишет по одному JSON-объекту на строку с шаблоном, отрендеренным сообщением и каждым именованным свойством.

В RE:NODE вкладка консоли показывает вывод процесса без фильтров и в реальном времени, рядом с графиками памяти, CPU и диска относительно лимитов тарифа, так что однострочная консоль с метками времени - это именно то, что вы будете читать, когда что-то пойдёт не так. Это не архив логов: если ошибки прошлого вторника понадобятся вам через месяц, пишите их туда, где они сохранятся.

Serilog: когда его стоит добавлять#

Serilog оправдывает себя, когда вам нужно одно из трёх, с чем встроенные провайдеры справляются плохо: ротация лог-файлов с ограничением хранения, обогащение (имя машины, ID запроса, ID пользователя в каждом событии) или отправка на сервер логов вроде Seq, Elasticsearch или Grafana Loki через sink. Настройка - это пакет и несколько строк:

$ 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-логгер ловит сбои при запуске, до загрузки конфигурации, - а это именно тот момент, когда отсутствующая переменная окружения роняет приложение, а стандартная настройка почти ничего не выводит. Log.CloseAndFlush() важен для асинхронных и пакетных sink-ов: без него последние сообщения перед падением остаются в буфере, когда процесс завершается.

UseSerilogRequestLogging() заменяет несколько строк фреймворка на запрос одной строкой с методом, путём, кодом статуса и затраченным временем - это и есть тот лог запросов, который большинству на самом деле нужен. Сочетайте его с переопределением Microsoft.AspNetCore на Warning, чтобы собственные строки фреймворка не писались вдобавок.

Конфигурация живёт в отдельной секции, которая заменяет Logging, как только за дело берётся Serilog:

{  "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        }      }    ]  }}

Если файлы вам не нужны, не пишите их. Приложению, которое пишет только в консоль и отправляет логи на сервер через sink, нечем заполнить диск. Логи, которые стоит хранить разбирает, что сохранять и как долго.

Health checks: liveness, readiness и зависимости#

Health check эндпоинт отвечает машине на один вопрос: может ли этот экземпляр обслуживать запросы прямо сейчас? ASP.NET Core содержит всю нужную обвязку из коробки.

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 берётся из пакета Microsoft.Extensions.Diagnostics.HealthChecks.EntityFrameworkCore и просто спрашивает у EF Core, может ли он подключиться. Для проверок базы данных без EF Core общественные пакеты AspNetCore.HealthChecks.* дают AddSqlServer, AddNpgSql, AddMySql, AddRedis и многое другое; они широко используются, но не входят во фреймворк, так что фиксируйте их версии, как любую другую зависимость.

Ответ - обычный текст: Healthy, Degraded или Unhealthy, а коды статуса по умолчанию сопоставлены так:

Разделение на liveness и readiness - та часть, которая предотвращает простои, а не вызывает их. Liveness спрашивает «жив ли процесс и не завис ли он» и не должен проверять ничего внешнего. Readiness спрашивает «может ли он обслуживать настоящие запросы», и именно здесь место базе данных. Если ваш единственный эндпоинт проверяет базу и что-то перезапускает приложение всякий раз, когда этот эндпоинт падает, пятисекундная заминка базы перезапустит все экземпляры разом, и все они одновременно начнут переподключаться. Liveness-проверка, которая не трогает ни одной зависимости, такого вызвать не может.

Собственная проверка - это класс, реализующий 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"]);

Задайте таймаут каждой проверке, которая ходит в сеть. Health эндпоинт, зависающий на тридцать секунд, хуже того, что возвращает 503, потому что то, что его опрашивает, может держать соединения открытыми, и они будут копиться.

Защита и публикация health эндпоинта#

Ответ по умолчанию - одно слово, и его безопасно отдавать наружу. Как только вы добавляете подробный writer - популярный UIResponseWriter.WriteHealthCheckUIResponse из AspNetCore.HealthChecks.UI.Client или собственный JSON с описанием и исключением каждой проверки, - вы публикуете имена своих зависимостей, а иногда и их сообщения об ошибках. Держите публичный эндпоинт лаконичным, а подробный уберите за авторизацию или ограничение по хосту:

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

Исключите health эндпоинты из логирования запросов, иначе монитор, опрашивающий раз в тридцать секунд, будет писать почти три тысячи пустых строк в день. В Serilog опция GetLevel у UseSerilogRequestLogging может опустить их до Verbose.

Знайте, что на самом деле будет вызывать эндпоинт. В RE:NODE наблюдатель за падениями платформы каждые две минуты проверяет, не пошёл ли uptime сервера назад и не ушёл ли сервер в офлайн, и открывает тикет после трёх неожиданных перезапусков за час. Он следит за процессом; ваш /healthz он не вызывает. Зависшее приложение, процесс которого жив и возвращает 503, им перезапущено не будет, поэтому направьте внешний uptime-монитор на readiness URL через ваш домен. Мониторинг, который что-то сообщает разбирает, на что ставить оповещения, а graceful shutdown и health checks - другую половину: переключение readiness в unhealthy, когда приложение останавливается, чтобы прокси перестал слать ему трафик до его завершения.

Логирование запросов, HTTP logging и корреляция#

Есть три инструмента уровня запросов, и они не взаимозаменяемы:

• Логирование запросов Serilog - одна итоговая строка на запрос. Правильный выбор по умолчанию.
• `AddHttpLogging` / `UseHttpLogging` - middleware HTTP-логирования из фреймворка, которое может включать заголовки и тела. Оно пишет на уровне Information в категорию Microsoft.AspNetCore.HttpLogging.HttpLoggingMiddleware, поэтому ничего не показывает, пока эту категорию не пропустит фильтр. Полезно для короткой сессии отладки; опасно, если оставить включённым, потому что заголовки содержат cookies и токены авторизации, если вы не ограничили RequestHeaders и ResponseHeaders.
• `AddW3CLogging` - журнал доступа в расширенном формате W3C, записываемый в файлы. Удобно, если у вас уже есть инструменты, читающие логи в стиле IIS.

Для корреляции у каждого запроса уже есть HttpContext.TraceIdentifier, а при стандартном отслеживании Activity каждое событие лога внутри запроса несёт TraceId и SpanId, если провайдер их записывает (JSON-форматтер консоли и Serilog оба умеют). Возвращайте trace ID в ответах с ошибкой - ProblemDetails по умолчанию включает расширение traceId, когда вы используете AddProblemDetails(), - и скриншот страницы ошибки от пользователя превращается в прямой поиск по вашим логам.

За обратным прокси адрес клиента в ваших логах запросов - это адрес прокси, пока вы не включите forwarded headers. Настоящий IP клиента приходит в X-Forwarded-For, а ASP.NET Core за обратным прокси показывает ForwardedHeadersOptions, которые делают HttpContext.Connection.RemoteIpAddress правильным, - а именно его читают и ваши логи, и любой ограничитель частоты запросов.

Решение проблем#

Ничего не логируется. Обычно был вызван ClearProviders(), а обратно ничего не добавили, или Serilog настроен, но его секция WriteTo пуста или написана с ошибкой. SelfLog.Enable(Console.Error) в Serilog выводит его собственные ошибки конфигурации.

Консоль завалена SQL. Microsoft.EntityFrameworkCore.Database.Command стоит на Information, явно или через Default. Добавьте переопределение на Warning.

Приложение падает при запуске без полезного вывода. Исключение произошло до настройки логирования. Используйте bootstrap-логгер (Serilog) или оберните builder.Build() и app.Run() в try/catch, который пишет в Console.Error, а потом читайте консоль с самого начала.

Health эндпоинт возвращает 503, а приложение работает. Одна из проверок с тегом этого эндпоинта падает или уходит в таймаут. Временно подключите подробный writer за авторизацией и посмотрите, какая именно; обычно это зависимость, которую эндпоинт вообще не должен был проверять.

Закончился диск. Сначала найдите каталог логов. Файловые sink-и с ротацией и хранением по умолчанию, оставленный включённым Debug и HTTP logging с телами - три обычные причины, именно в этом порядке.

В строках лога у каждого клиента адрес прокси. Forwarded headers не настроены, или KnownProxies не включает адрес прокси, поэтому middleware игнорирует заголовок.

FAQ#

Нужен ли мне Serilog, или встроенного логирования достаточно?

Встроенного ILogger с JSON-форматтером консоли достаточно для приложения, логи которого читают в консоли или собирают со стандартного вывода. Serilog стоит добавить ради ротации файлов с ограничением хранения, обогащения каждого события или sink-а на сервер логов. Ваш код в любом случае продолжает вызывать ILogger, так что переход позже обойдётся одним изменением настройки.

На каком уровне логов должен работать продакшен?

Information для ваших собственных категорий, Warning для Microsoft.AspNetCore и EF Core. Когда ищете проблему, временно поднимите одну категорию до Debug через переменную окружения, а потом верните обратно.

Должен ли health check проверять базу данных?

Readiness-проверка должна, потому что приложение, которое не может достучаться до базы, не может обслужить большинство запросов. Liveness-проверка не должна, потому что перезапуск приложения не чинит базу, а перезапуск всех экземпляров разом замедляет восстановление.

Почему в выводе нет моих структурированных свойств?

Либо сообщение собрано через интерполяцию строк, и захватывать нечего, либо провайдер - обычный простой консольный форматтер, который рендерит предложение и отбрасывает поля. Используйте шаблон сообщения и структурированный форматтер или sink.

Как часто монитор должен вызывать health эндпоинт?

Для небольшого приложения достаточно раз в 30-60 секунд. Чаще - это лишняя нагрузка и шум в логах, при том что о проблеме вы узнаете ненамного раньше, а оповещение после двух неудач подряд избавит вас от тревоги из-за одного медленного ответа.