From 443eebe862e18b6dd8149b085d32cd819ffb7eef Mon Sep 17 00:00:00 2001 From: nns Date: Thu, 28 May 2026 17:46:17 +0500 Subject: [PATCH] =?UTF-8?q?feat(logging):=20=D1=81=D1=82=D1=80=D1=83=D0=BA?= =?UTF-8?q?=D1=82=D1=83=D1=80=D0=BD=D1=8B=D0=B5=20log-fields=20=D0=B2=20Se?= =?UTF-8?q?rilog=20(TD-4)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LogEnrichmentMiddleware: после Authentication+Authorization вытягивает из ClaimsPrincipal OrgId (claim org_id) и UserId (sub/NameIdentifier), плюс CorrelationId из заголовка X-Correlation-ID (или генерирует Guid). Все три кладутся в Serilog LogContext через PushProperty — каждая ILogger.Log* внутри пайплайна автоматически получает эти поля как структурные properties (не текст), пригодные для фильтрации в Loki/ELK без regex. Эхо CorrelationId в response-header — клиент видит id для support. Business-логи (структурные плейсхолдеры, не string interpolation): - Supply.Post → "Supply posted: {SupplyNumber} supplier={SupplierId} store={StoreId} lines={LinesCount} total={Total}". - RetailSale.Post → "RetailSale posted: {SaleNumber} store={StoreId} payment={Payment} lines={LinesCount} total={Total}". docs/logging.md — паттерн, anti-pattern'ы (string interpolation, PII в логах, токены/пароли), correlation-id workflow. Co-Authored-By: Claude Opus 4.7 --- docs/logging.md | 79 +++++++++++++++++++ .../Purchases/SuppliesController.cs | 11 ++- .../Sales/RetailSalesController.cs | 7 +- .../Observability/LogEnrichmentMiddleware.cs | 38 +++++++++ src/food-market.api/Program.cs | 4 + 5 files changed, 137 insertions(+), 2 deletions(-) create mode 100644 docs/logging.md create mode 100644 src/food-market.api/Infrastructure/Observability/LogEnrichmentMiddleware.cs diff --git a/docs/logging.md b/docs/logging.md new file mode 100644 index 0000000..0ffb56e --- /dev/null +++ b/docs/logging.md @@ -0,0 +1,79 @@ +# Логирование (Serilog) + +Структурные логи через Serilog. На каждый HTTP-запрос автоматически +обогащаются метки `CorrelationId`, `OrgId`, `UserId` через +`LogEnrichmentMiddleware`. Любой `ILogger<…>.Log*` внутри пайплайна +наследует эти свойства — не нужно тащить их в каждый вызов руками. + +## Где приземляются логи + +Текущая конфигурация (см. `appsettings.json` / `Program.cs`): +- **Console** (Serilog.Sinks.Console) — в dev и docker (stdout читается + docker logs / journalctl); +- **File** (Serilog.Sinks.File) — ротация по дням. + +Для прод-ELK/Loki в будущем добавляется `Serilog.Sinks.Elasticsearch` +или `Serilog.Sinks.Grafana.Loki`; формат вывода уже JSON-friendly, +кардинальность лейблов под Loki не вылезает (`OrgId` гранулярный, но +не на каждое движение, плюс ограничен текущим парком орг ≪10k). + +## Корреляция между запросами + +Заголовок `X-Correlation-ID`: +- если клиент прислал — middleware его уважает (для bridging с upstream'ом); +- если нет — генерируется `Guid.NewGuid("N")`. + +Эхо в response-header чтобы клиент при ошибке отдал support'у конкретный id. + +```bash +curl -i http://localhost:5081/api/me -H "Authorization: Bearer …" +# < X-Correlation-ID: 7f9b3c1a4e5d4f0a8b1c2d3e4f5a6b7c +``` + +## Структурные бизнес-логи + +В коде используем именованные плейсхолдеры — Serilog кладёт каждое +поле как отдельное property в LogEvent. Это позволяет фильтровать +`OrgId = "..." AND SupplyNumber = "..."` без regex'ов. + +Хорошо: +```csharp +_log.LogInformation( + "Supply posted: {SupplyNumber} supplier={SupplierId} store={StoreId} lines={LinesCount} total={Total}", + supply.Number, supply.SupplierId, supply.StoreId, supply.Lines.Count, supply.Total); +``` + +Плохо (теряем структуру, нельзя фильтровать): +```csharp +_log.LogInformation($"Supply posted: {supply.Number} ..."); // string interpolation +``` + +## Что уже логируется как business event + +- `Supply posted` — после успешного `/api/purchases/supplies/{id}/post`. +- `RetailSale posted` — после успешного `/api/sales/retail/{id}/post`. + +В развитии: Demand.Post, Transfer.Post, Inventory.Post, Loss.Post — +по тому же паттерну. Метки разные, имя события одинаковое для +аналитики «сколько проведений в час по типам». + +## Запросы (Serilog request logging) + +`app.UseSerilogRequestLogging()` пишет одну summary-строку на каждый +HTTP-запрос: метод, путь, статус, длительность. Дополнительно +обогащается `OrgId/UserId/CorrelationId` из LogContext. + +Шаблон в логе: +``` +HTTP POST /api/purchases/supplies/{id}/post responded 204 in 87.3ms +{ OrgId: "8b0f...", UserId: "57c3...", CorrelationId: "7f9b..." } +``` + +## Анти-паттерны + +- **Не логировать токены/пароли/email-пароли** — даже структурно. + Identity events (SignIn / Reset Password) — нет, только статус и user-id. +- **Не логировать тело запроса целиком** — может содержать PII. + Только конкретные поля по необходимости. +- **Не использовать string interpolation в шаблоне** — теряется + структура (выше). diff --git a/src/food-market.api/Controllers/Purchases/SuppliesController.cs b/src/food-market.api/Controllers/Purchases/SuppliesController.cs index ac39ba1..c2eff39 100644 --- a/src/food-market.api/Controllers/Purchases/SuppliesController.cs +++ b/src/food-market.api/Controllers/Purchases/SuppliesController.cs @@ -18,11 +18,13 @@ public class SuppliesController : ControllerBase { private readonly AppDbContext _db; private readonly IStockService _stock; + private readonly ILogger _log; - public SuppliesController(AppDbContext db, IStockService stock) + public SuppliesController(AppDbContext db, IStockService stock, ILogger log) { _db = db; _stock = stock; + _log = log; } public record SupplyListRow( @@ -381,6 +383,13 @@ public async Task Post(Guid id, CancellationToken ct) return Conflict(new { error = "Документ проводится параллельно другим запросом. Повторите попытку." }); } foodmarket.Api.Infrastructure.Observability.AppMetrics.IncrementPosted("supply"); + // Structured business log: лейблы Number/SupplierId/StoreId/LinesCount/Total + // попадут в Serilog как отдельные свойства, не часть текста — удобно + // фильтровать в Loki/ELK без regex'ов. CorrelationId/OrgId/UserId + // подмешает LogEnrichmentMiddleware из LogContext. + _log.LogInformation( + "Supply posted: {SupplyNumber} supplier={SupplierId} store={StoreId} lines={LinesCount} total={Total}", + supply.Number, supply.SupplierId, supply.StoreId, supply.Lines.Count, supply.Total); return NoContent(); } diff --git a/src/food-market.api/Controllers/Sales/RetailSalesController.cs b/src/food-market.api/Controllers/Sales/RetailSalesController.cs index c63e431..b26c6e2 100644 --- a/src/food-market.api/Controllers/Sales/RetailSalesController.cs +++ b/src/food-market.api/Controllers/Sales/RetailSalesController.cs @@ -18,11 +18,13 @@ public class RetailSalesController : ControllerBase { private readonly AppDbContext _db; private readonly IStockService _stock; + private readonly ILogger _log; - public RetailSalesController(AppDbContext db, IStockService stock) + public RetailSalesController(AppDbContext db, IStockService stock, ILogger log) { _db = db; _stock = stock; + _log = log; } public record RetailSaleListRow( @@ -417,6 +419,9 @@ public async Task Post(Guid id, CancellationToken ct) await _db.SaveChangesAsync(ct); await tx.CommitAsync(ct); foodmarket.Api.Infrastructure.Observability.AppMetrics.IncrementPosted("retail-sale"); + _log.LogInformation( + "RetailSale posted: {SaleNumber} store={StoreId} payment={Payment} lines={LinesCount} total={Total}", + sale.Number, sale.StoreId, sale.Payment, sale.Lines.Count, sale.Total); return NoContent(); } diff --git a/src/food-market.api/Infrastructure/Observability/LogEnrichmentMiddleware.cs b/src/food-market.api/Infrastructure/Observability/LogEnrichmentMiddleware.cs new file mode 100644 index 0000000..ebd8226 --- /dev/null +++ b/src/food-market.api/Infrastructure/Observability/LogEnrichmentMiddleware.cs @@ -0,0 +1,38 @@ +using System.Security.Claims; +using foodmarket.Api.Infrastructure.Tenancy; +using Serilog.Context; + +namespace foodmarket.Api.Infrastructure.Observability; + +/// Обогащает каждый HTTP-запрос структурными лейблами в Serilog +/// LogContext: OrgId, UserId, CorrelationId. Любая ILogger.Log<…> +/// внутри пайплайна автоматически получит эти свойства — не надо +/// тащить их явно в каждый вызов. +/// +/// CorrelationId: берётся из заголовка X-Correlation-ID если есть, +/// иначе генерируется Guid. Эхо в response-header чтобы клиент видел +/// id для последующего запроса в support. +public sealed class LogEnrichmentMiddleware +{ + private const string HeaderName = "X-Correlation-ID"; + private readonly RequestDelegate _next; + + public LogEnrichmentMiddleware(RequestDelegate next) => _next = next; + + public async Task InvokeAsync(HttpContext ctx) + { + var correlationId = ctx.Request.Headers.TryGetValue(HeaderName, out var hdr) && !string.IsNullOrWhiteSpace(hdr) + ? hdr.ToString() + : Guid.NewGuid().ToString("N"); + ctx.Response.Headers[HeaderName] = correlationId; + + var orgId = ctx.User?.FindFirst(HttpContextTenantContext.OrganizationClaim)?.Value; + var userId = ctx.User?.FindFirst(ClaimTypes.NameIdentifier)?.Value + ?? ctx.User?.FindFirst("sub")?.Value; + + using var c = LogContext.PushProperty("CorrelationId", correlationId); + using var o = orgId is null ? null : LogContext.PushProperty("OrgId", orgId); + using var u = userId is null ? null : LogContext.PushProperty("UserId", userId); + await _next(ctx); + } +} diff --git a/src/food-market.api/Program.cs b/src/food-market.api/Program.cs index 2127966..f236633 100644 --- a/src/food-market.api/Program.cs +++ b/src/food-market.api/Program.cs @@ -302,6 +302,10 @@ [new Microsoft.OpenApi.Models.OpenApiSecurityScheme app.UseRateLimiter(); app.UseAuthentication(); app.UseAuthorization(); + // После аутентификации, до контроллеров: вытягиваем OrgId/UserId из ClaimsPrincipal + // и кладём в Serilog LogContext вместе с CorrelationId — каждая ILogger.Log + // в пайплайне автоматически получит эти лейблы. + app.UseMiddleware(); // SuperAdmin «открыть как…» — тот же tenant как у выбранной орги, но // только GET. Любая мутация → 403, кроме /api/super-admin/* и /connect/*. app.UseMiddleware();