feat(logging): структурные log-fields в Serilog (TD-4)

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 <noreply@anthropic.com>
This commit is contained in:
nns 2026-05-28 17:46:17 +05:00
parent f936cd26c2
commit 443eebe862
5 changed files with 137 additions and 2 deletions

79
docs/logging.md Normal file
View file

@ -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 в шаблоне** — теряется
структура (выше).

View file

@ -18,11 +18,13 @@ public class SuppliesController : ControllerBase
{ {
private readonly AppDbContext _db; private readonly AppDbContext _db;
private readonly IStockService _stock; private readonly IStockService _stock;
private readonly ILogger<SuppliesController> _log;
public SuppliesController(AppDbContext db, IStockService stock) public SuppliesController(AppDbContext db, IStockService stock, ILogger<SuppliesController> log)
{ {
_db = db; _db = db;
_stock = stock; _stock = stock;
_log = log;
} }
public record SupplyListRow( public record SupplyListRow(
@ -381,6 +383,13 @@ public async Task<IActionResult> Post(Guid id, CancellationToken ct)
return Conflict(new { error = "Документ проводится параллельно другим запросом. Повторите попытку." }); return Conflict(new { error = "Документ проводится параллельно другим запросом. Повторите попытку." });
} }
foodmarket.Api.Infrastructure.Observability.AppMetrics.IncrementPosted("supply"); 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(); return NoContent();
} }

View file

@ -18,11 +18,13 @@ public class RetailSalesController : ControllerBase
{ {
private readonly AppDbContext _db; private readonly AppDbContext _db;
private readonly IStockService _stock; private readonly IStockService _stock;
private readonly ILogger<RetailSalesController> _log;
public RetailSalesController(AppDbContext db, IStockService stock) public RetailSalesController(AppDbContext db, IStockService stock, ILogger<RetailSalesController> log)
{ {
_db = db; _db = db;
_stock = stock; _stock = stock;
_log = log;
} }
public record RetailSaleListRow( public record RetailSaleListRow(
@ -417,6 +419,9 @@ public async Task<IActionResult> Post(Guid id, CancellationToken ct)
await _db.SaveChangesAsync(ct); await _db.SaveChangesAsync(ct);
await tx.CommitAsync(ct); await tx.CommitAsync(ct);
foodmarket.Api.Infrastructure.Observability.AppMetrics.IncrementPosted("retail-sale"); 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(); return NoContent();
} }

View file

@ -0,0 +1,38 @@
using System.Security.Claims;
using foodmarket.Api.Infrastructure.Tenancy;
using Serilog.Context;
namespace foodmarket.Api.Infrastructure.Observability;
/// <summary>Обогащает каждый HTTP-запрос структурными лейблами в Serilog
/// LogContext: OrgId, UserId, CorrelationId. Любая ILogger.Log<…>
/// внутри пайплайна автоматически получит эти свойства — не надо
/// тащить их явно в каждый вызов.
///
/// CorrelationId: берётся из заголовка <c>X-Correlation-ID</c> если есть,
/// иначе генерируется Guid. Эхо в response-header чтобы клиент видел
/// id для последующего запроса в support.</summary>
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);
}
}

View file

@ -302,6 +302,10 @@ [new Microsoft.OpenApi.Models.OpenApiSecurityScheme
app.UseRateLimiter(); app.UseRateLimiter();
app.UseAuthentication(); app.UseAuthentication();
app.UseAuthorization(); app.UseAuthorization();
// После аутентификации, до контроллеров: вытягиваем OrgId/UserId из ClaimsPrincipal
// и кладём в Serilog LogContext вместе с CorrelationId — каждая ILogger.Log
// в пайплайне автоматически получит эти лейблы.
app.UseMiddleware<foodmarket.Api.Infrastructure.Observability.LogEnrichmentMiddleware>();
// SuperAdmin «открыть как…» — тот же tenant как у выбранной орги, но // SuperAdmin «открыть как…» — тот же tenant как у выбранной орги, но
// только GET. Любая мутация → 403, кроме /api/super-admin/* и /connect/*. // только GET. Любая мутация → 403, кроме /api/super-admin/* и /connect/*.
app.UseMiddleware<foodmarket.Api.Infrastructure.Tenancy.ReadonlyOverrideMiddleware>(); app.UseMiddleware<foodmarket.Api.Infrastructure.Tenancy.ReadonlyOverrideMiddleware>();