From 0a9334a6b3cfc327f9d2026f3dfb20510041aaa7 Mon Sep 17 00:00:00 2001 From: Everton William Thoele Schuster Date: Mon, 5 Oct 2026 13:29:07 -0300 Subject: [PATCH 1/4] =?UTF-8?q?feat(backend):=20logs=20leg=C3=ADveis=20com?= =?UTF-8?q?=20Serilog=20em=20todos=20os=20hosts=20.NET,=20numa=20bibliotec?= =?UTF-8?q?a=20compartilhada?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Cria backend/shared/Admin.Logging, o único lugar que define como um processo .NET registra logs, e a liga ao AddServiceDefaults() e ao AppHost. Um serviço novo ganha formato, níveis, exportação OTLP e a linha por requisição sem tocar no Program.cs nem no appsettings. - Console: [HH:mm:ss LVL] Contexto: mensagem, cultura invariante, cores só em Development (e nunca com NO_COLOR). - Níveis padrão em código; Serilog:MinimumLevel em configuração só sobrescreve por host. EF Database.Command, HttpClient e Polly passam a Warning; OpenIddict fica em Information. - Exportação estruturada pelo Serilog.Sinks.OpenTelemetry, lendo as variáveis OTEL_* do Aspire, só quando o endpoint existe. - Uma linha por requisição por um IStartupFilter (fora do UseExceptionHandler, então um 500 sai com o status). Sem query string; caracteres de controle removidos do path (CWE-117); /health, /alive e arquivos sem endpoint ficam em Verbose. - Logging:LogLevel deixa de ser lido; os blocos antigos e o AppHost/appsettings.Development.json (redundante) saem. - ADR 0054, ARCHITECTURE §1 e §8, QUALITY e READMEs atualizados. Admin.Logging tem projeto de testes próprio com gate de cobertura. Co-Authored-By: Claude Sonnet 5.5 --- backend/AGENTS.md | 2 + backend/AdminBackend.slnx | 2 + backend/AppHost/AppHost.cs | 4 + backend/AppHost/AppHost.csproj | 1 + backend/AppHost/appsettings.Development.json | 8 -- backend/AppHost/appsettings.json | 10 +- backend/Directory.Packages.props | 4 + backend/README.md | 4 +- backend/ServiceDefaults/Extensions.cs | 19 ++- .../ServiceDefaults/ServiceDefaults.csproj | 4 + backend/docs/ARCHITECTURE.md | 16 ++- .../appsettings.Development.json | 6 - .../IdentityService.Api/appsettings.json | 6 - .../appsettings.Development.json | 6 - .../ServicesService.Api/appsettings.json | 6 - .../Admin.Logging.Tests.csproj | 29 ++++ .../ReadableConsoleTests.cs | 99 +++++++++++++ .../ReadableLoggingExtensionsTests.cs | 104 ++++++++++++++ .../RequestLoggingTests.cs | 135 ++++++++++++++++++ .../shared/Admin.Logging.Tests/TestSinks.cs | 32 +++++ .../shared/Admin.Logging/Admin.Logging.csproj | 26 ++++ .../shared/Admin.Logging/ReadableConsole.cs | 44 ++++++ .../ReadableLoggingExtensions.cs | 65 +++++++++ .../Admin.Logging/RequestLoggingExtensions.cs | 16 +++ .../RequestLoggingStartupFilter.cs | 82 +++++++++++ docs/MONOREPO.md | 4 +- docs/QUALITY.md | 4 +- .../0054-serilog-readable-console-logging.md | 67 +++++++++ docs/adr/README.md | 3 +- 29 files changed, 756 insertions(+), 52 deletions(-) delete mode 100644 backend/AppHost/appsettings.Development.json create mode 100644 backend/shared/Admin.Logging.Tests/Admin.Logging.Tests.csproj create mode 100644 backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs create mode 100644 backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs create mode 100644 backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs create mode 100644 backend/shared/Admin.Logging.Tests/TestSinks.cs create mode 100644 backend/shared/Admin.Logging/Admin.Logging.csproj create mode 100644 backend/shared/Admin.Logging/ReadableConsole.cs create mode 100644 backend/shared/Admin.Logging/ReadableLoggingExtensions.cs create mode 100644 backend/shared/Admin.Logging/RequestLoggingExtensions.cs create mode 100644 backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs create mode 100644 docs/adr/0054-serilog-readable-console-logging.md diff --git a/backend/AGENTS.md b/backend/AGENTS.md index 41f0d0e8..09bdda1b 100644 --- a/backend/AGENTS.md +++ b/backend/AGENTS.md @@ -45,6 +45,8 @@ Cada linha é um lembrete; a regra, com o porquê, está na seção indicada da unicidade; migração só aditiva.** [§5](docs/ARCHITECTURE.md#5-tenancy-and-persistence) - **Controller sem lógica; enum no fio é string.** [§6](docs/ARCHITECTURE.md#6-http-surface) - **UTC, sempre.** [§7](docs/ARCHITECTURE.md#7-time) +- **Log com `ILogger` e template com placeholders, nunca string interpolada; nível em `Serilog:MinimumLevel`.** + [§8](docs/ARCHITECTURE.md#logging) - **Corpo em bloco com guard clauses; sem comentário de "o quê".** [§8](docs/ARCHITECTURE.md#8-code-style) ## Portões diff --git a/backend/AdminBackend.slnx b/backend/AdminBackend.slnx index 237f40a6..b5c95a8f 100644 --- a/backend/AdminBackend.slnx +++ b/backend/AdminBackend.slnx @@ -17,6 +17,8 @@ + + diff --git a/backend/AppHost/AppHost.cs b/backend/AppHost/AppHost.cs index d939933d..721bbd37 100644 --- a/backend/AppHost/AppHost.cs +++ b/backend/AppHost/AppHost.cs @@ -1,5 +1,9 @@ +using Admin.Logging; + var builder = DistributedApplication.CreateBuilder(args); +builder.Services.AddReadableLogging(builder.Configuration, builder.Environment); + var developmentPassword = builder.AddParameter( "development-password", "postgres", diff --git a/backend/AppHost/AppHost.csproj b/backend/AppHost/AppHost.csproj index 34bfd0fe..084310fa 100644 --- a/backend/AppHost/AppHost.csproj +++ b/backend/AppHost/AppHost.csproj @@ -20,6 +20,7 @@ + diff --git a/backend/AppHost/appsettings.Development.json b/backend/AppHost/appsettings.Development.json deleted file mode 100644 index 0c208ae9..00000000 --- a/backend/AppHost/appsettings.Development.json +++ /dev/null @@ -1,8 +0,0 @@ -{ - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning" - } - } -} diff --git a/backend/AppHost/appsettings.json b/backend/AppHost/appsettings.json index 31c092aa..b51acacc 100644 --- a/backend/AppHost/appsettings.json +++ b/backend/AppHost/appsettings.json @@ -1,9 +1,9 @@ { - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning", - "Aspire.Hosting.Dcp": "Warning" + "Serilog": { + "MinimumLevel": { + "Override": { + "Aspire.Hosting.Dcp": "Warning" + } } } } diff --git a/backend/Directory.Packages.props b/backend/Directory.Packages.props index ac4096ff..0f3c9ab1 100644 --- a/backend/Directory.Packages.props +++ b/backend/Directory.Packages.props @@ -15,6 +15,10 @@ + + + + diff --git a/backend/README.md b/backend/README.md index ddc52be8..6fa7000c 100644 --- a/backend/README.md +++ b/backend/README.md @@ -20,9 +20,9 @@ services// ├── .Api/ ASP.NET Core controllers — → Application + Infrastructure ├── .Tests/ unit tests of Domain + Application └── .PersistenceTests/ EF InMemory tenant tests, where a service needs them -shared/ cross-cutting infrastructure — never business rules +shared/ cross-cutting infrastructure (incl. Admin.Logging) — never business rules AppHost/ .NET Aspire, local orchestration only -ServiceDefaults/ OpenTelemetry, health checks, service discovery +ServiceDefaults/ logging (via Admin.Logging), OpenTelemetry, health checks, service discovery ``` Each service is one business context with its own schema and database role. The project-reference diff --git a/backend/ServiceDefaults/Extensions.cs b/backend/ServiceDefaults/Extensions.cs index a2352485..c3e51742 100644 --- a/backend/ServiceDefaults/Extensions.cs +++ b/backend/ServiceDefaults/Extensions.cs @@ -1,8 +1,8 @@ +using Admin.Logging; using Microsoft.AspNetCore.Builder; using Microsoft.AspNetCore.Diagnostics.HealthChecks; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Diagnostics.HealthChecks; -using Microsoft.Extensions.Logging; using Microsoft.Extensions.ServiceDiscovery; using OpenTelemetry; using OpenTelemetry.Metrics; @@ -17,6 +17,8 @@ public static class Extensions public static TBuilder AddServiceDefaults(this TBuilder builder) where TBuilder : IHostApplicationBuilder { + builder.ConfigureLogging(); + builder.ConfigureOpenTelemetry(); builder.AddDefaultHealthChecks(); @@ -33,14 +35,17 @@ public static TBuilder AddServiceDefaults(this TBuilder builder) where return builder; } - public static TBuilder ConfigureOpenTelemetry(this TBuilder builder) where TBuilder : IHostApplicationBuilder + public static TBuilder ConfigureLogging(this TBuilder builder) where TBuilder : IHostApplicationBuilder { - builder.Logging.AddOpenTelemetry(logging => - { - logging.IncludeFormattedMessage = true; - logging.IncludeScopes = true; - }); + builder.Services.AddReadableLogging(builder.Configuration, builder.Environment, colorWhenRedirected: true); + + builder.Services.AddRequestLogging(HealthEndpointPath, AlivenessEndpointPath); + return builder; + } + + public static TBuilder ConfigureOpenTelemetry(this TBuilder builder) where TBuilder : IHostApplicationBuilder + { builder.Services.AddOpenTelemetry() .WithMetrics(metrics => { diff --git a/backend/ServiceDefaults/ServiceDefaults.csproj b/backend/ServiceDefaults/ServiceDefaults.csproj index 8128a10a..b11d6f0e 100644 --- a/backend/ServiceDefaults/ServiceDefaults.csproj +++ b/backend/ServiceDefaults/ServiceDefaults.csproj @@ -19,4 +19,8 @@ + + + + diff --git a/backend/docs/ARCHITECTURE.md b/backend/docs/ARCHITECTURE.md index 0251e36c..29c162ee 100644 --- a/backend/docs/ARCHITECTURE.md +++ b/backend/docs/ARCHITECTURE.md @@ -49,8 +49,9 @@ that wraps two stores in one transaction. Don't carry its specifics into a busin A new service copies the project set below, the per-service `Domain/Common/` types, a schema and a role in `infra/postgres/init/`, a schema-scoped migrations history table, and an AppHost resource; -it registers `TenantHeaderFilter` if it serves tenant-owned resources. Use the live services as the -template, not a copied snippet ([`docs/MONOREPO.md`](../../docs/MONOREPO.md)). +it registers `TenantHeaderFilter` if it serves tenant-owned resources. `AddServiceDefaults()` already +brings logging, telemetry and health checks, so there is nothing to copy for them. Use the live services +as the template, not a copied snippet ([`docs/MONOREPO.md`](../../docs/MONOREPO.md)). ### Projects and dependency direction @@ -74,6 +75,7 @@ Shared projects in `backend/shared/` hold infrastructure, never business rules: | `Admin.SharedKernel.AspNetCore` | `ToActionResult`, `ApiResponse`, `ApiProblemDetails`, `AgenzaControllerBase`, `GenericExceptionHandler` | Api | | `Admin.SharedKernel.EntityFrameworkCore` | `RepositoryBase`, `ApplyAuditableConventions` (soft-delete and tenant filters) | Infrastructure | | `Admin.Identity.Client` | JWT validation, `ITenantAccessor`, `ICurrentUserAccessor`, `TenantHeaderFilter`, `[IgnoreTenant]` | Infrastructure, Api | +| `Admin.Logging` | the Serilog pipeline: console format, default levels, OTLP export, one line per request | `ServiceDefaults`, `AppHost` — never a layer | `BaseEntity`, `TenantOwnedEntity`, `DomainResult` and `DomainError` are **duplicated per service on purpose** — Domain references nothing, so it cannot share them @@ -354,6 +356,16 @@ Older code is converted when touched, not in bulk. No "what" comments and no XML doc comments; a one-line "why" only for a genuine race or a non-obvious constraint (root [`AGENTS.md`](../../AGENTS.md)). Rationale belongs in an ADR. +### Logging + +Inject `ILogger` and write a message template with named placeholders, never an interpolated string. Serilog is +the pipeline behind it, owned by `Admin.Logging` and brought in by `AddServiceDefaults()` +([0054](../../docs/adr/0054-serilog-readable-console-logging.md)): a service configures nothing. Domain and Application +stay on `Microsoft.Extensions.Logging.Abstractions` and nothing calls the static `Log`. The default levels live in +`Admin.Logging`; a host that needs another level sets it under `Serilog:MinimumLevel` in its `appsettings.json` +(`Logging:LogLevel` is ignored). A message carries constraint names, codes and ids, not request input; when it must, +strip control characters first (CWE-117), as `GenericExceptionHandler` and the request line do. + ## 9. Tests | Tier | Project | Proves | Tools | diff --git a/backend/services/identity-service/IdentityService.Api/appsettings.Development.json b/backend/services/identity-service/IdentityService.Api/appsettings.Development.json index d8df39ad..46412a15 100644 --- a/backend/services/identity-service/IdentityService.Api/appsettings.Development.json +++ b/backend/services/identity-service/IdentityService.Api/appsettings.Development.json @@ -1,10 +1,4 @@ { - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning" - } - }, "ConnectionStrings": { "Default": "Host=localhost;Port=5432;Database=appdb;Username=identity_app;Password=postgres" }, diff --git a/backend/services/identity-service/IdentityService.Api/appsettings.json b/backend/services/identity-service/IdentityService.Api/appsettings.json index 36f03eee..05348358 100644 --- a/backend/services/identity-service/IdentityService.Api/appsettings.json +++ b/backend/services/identity-service/IdentityService.Api/appsettings.json @@ -1,10 +1,4 @@ { - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning" - } - }, "AllowedHosts": "*", "DatabaseBootstrap": { "RunOnStartup": false diff --git a/backend/services/services-service/ServicesService.Api/appsettings.Development.json b/backend/services/services-service/ServicesService.Api/appsettings.Development.json index 1977feaa..020d7844 100644 --- a/backend/services/services-service/ServicesService.Api/appsettings.Development.json +++ b/backend/services/services-service/ServicesService.Api/appsettings.Development.json @@ -1,10 +1,4 @@ { - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning" - } - }, "ConnectionStrings": { "Default": "Host=localhost;Port=5432;Database=appdb;Username=services_app;Password=postgres" }, diff --git a/backend/services/services-service/ServicesService.Api/appsettings.json b/backend/services/services-service/ServicesService.Api/appsettings.json index 36f03eee..05348358 100644 --- a/backend/services/services-service/ServicesService.Api/appsettings.json +++ b/backend/services/services-service/ServicesService.Api/appsettings.json @@ -1,10 +1,4 @@ { - "Logging": { - "LogLevel": { - "Default": "Information", - "Microsoft.AspNetCore": "Warning" - } - }, "AllowedHosts": "*", "DatabaseBootstrap": { "RunOnStartup": false diff --git a/backend/shared/Admin.Logging.Tests/Admin.Logging.Tests.csproj b/backend/shared/Admin.Logging.Tests/Admin.Logging.Tests.csproj new file mode 100644 index 00000000..5df2f6cc --- /dev/null +++ b/backend/shared/Admin.Logging.Tests/Admin.Logging.Tests.csproj @@ -0,0 +1,29 @@ + + + + net10.0 + enable + enable + false + + + + + + + + + + + + + + + + + + + + + + diff --git a/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs b/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs new file mode 100644 index 00000000..280f9e90 --- /dev/null +++ b/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs @@ -0,0 +1,99 @@ +using System.Globalization; +using Serilog; + +namespace Admin.Logging.Tests; + +public class ReadableConsoleTests +{ + [Fact] + public void Format_ShortensTheSourceContextToItsLastSegment() + { + var output = Render(colors: false, logger => logger + .ForContext("SourceContext", "ServicesService.Application.Clients.CreateClientCommandHandler") + .Information("Client {ClientId} created", 42)); + + output.Should().MatchRegex(@"^\[\d{2}:\d{2}:\d{2} INF\] CreateClientCommandHandler: Client 42 created\n$"); + } + + [Fact] + public void Format_WithoutASourceContext_OmitsIt() + { + var output = Render(colors: false, logger => logger.Warning("Something odd")); + + output.Should().MatchRegex(@"^\[\d{2}:\d{2}:\d{2} WRN\] Something odd\n$"); + } + + [Fact] + public void Format_WithAnException_WritesItAfterTheMessageLine() + { + var output = Render(colors: false, logger => logger.Error(new InvalidOperationException("boom"), "Save failed")); + + var lines = output.Split('\n'); + lines[0].Should().EndWith("Save failed"); + lines[1].Should().Contain("InvalidOperationException: boom"); + } + + [Fact] + public void Format_UsesTheInvariantCulture() + { + var previous = CultureInfo.CurrentCulture; + CultureInfo.CurrentCulture = new CultureInfo("pt-BR"); + + try + { + var output = Render(colors: false, logger => logger.Information("took {Elapsed:0.0000} ms", 35.8)); + + output.Should().Contain("took 35.8000 ms"); + } + finally + { + CultureInfo.CurrentCulture = previous; + } + } + + [Fact] + public void Format_WithColors_EmitsAnsiCodesEvenWhenOutputIsRedirected() + { + var output = Render(colors: true, logger => logger.Information("hello")); + + output.Should().Contain("\u001b["); + } + + [Fact] + public void Format_WithoutColors_EmitsNoAnsiCodes() + { + var output = Render(colors: false, logger => logger.Information("hello")); + + output.Should().NotContain("\u001b["); + } + + [Theory] + [InlineData(true, false, false, false, true)] + [InlineData(true, false, true, false, false)] + [InlineData(true, false, true, true, true)] + [InlineData(true, true, false, true, false)] + [InlineData(false, false, false, true, false)] + public void ShouldUseColors_FollowsEnvironmentRedirectionAndNoColor( + bool isDevelopment, + bool noColorRequested, + bool outputRedirected, + bool colorWhenRedirected, + bool expected) + { + var colors = ReadableConsole.ShouldUseColors(isDevelopment, noColorRequested, outputRedirected, colorWhenRedirected); + + colors.Should().Be(expected); + } + + private static string Render(bool colors, Action write) + { + var output = new StringWriter(); + var logger = new LoggerConfiguration() + .WriteTo.Sink(new FormattingSink(ReadableConsole.CreateFormatter(colors), output)) + .CreateLogger(); + + write(logger); + + return output.ToString(); + } +} diff --git a/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs new file mode 100644 index 00000000..81723d64 --- /dev/null +++ b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs @@ -0,0 +1,104 @@ +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using NSubstitute; +using Serilog; + +namespace Admin.Logging.Tests; + +public class ReadableLoggingExtensionsTests +{ + [Fact] + public void AddReadableLogging_LogsFromInformationByDefault() + { + using var provider = BuildProvider(); + var logger = provider.GetRequiredService().CreateLogger("Some.Application.Handler"); + + logger.IsEnabled(LogLevel.Information).Should().BeTrue(); + logger.IsEnabled(LogLevel.Debug).Should().BeFalse(); + } + + [Theory] + [InlineData("Microsoft.AspNetCore.Hosting.Diagnostics")] + [InlineData("Microsoft.EntityFrameworkCore.Database.Command")] + [InlineData("System.Net.Http.HttpClient.Default.ClientHandler")] + [InlineData("Polly")] + public void AddReadableLogging_QuietsNoisyFrameworkCategories(string category) + { + using var provider = BuildProvider(); + var logger = provider.GetRequiredService().CreateLogger(category); + + logger.IsEnabled(LogLevel.Information).Should().BeFalse(); + logger.IsEnabled(LogLevel.Warning).Should().BeTrue(); + } + + [Fact] + public void AddReadableLogging_KeepsMigrationAndAuthenticationCategoriesAtInformation() + { + using var provider = BuildProvider(); + var factory = provider.GetRequiredService(); + + factory.CreateLogger("Microsoft.EntityFrameworkCore.Migrations").IsEnabled(LogLevel.Information).Should().BeTrue(); + factory.CreateLogger("OpenIddict.Server.OpenIddictServerDispatcher").IsEnabled(LogLevel.Information).Should().BeTrue(); + } + + [Fact] + public void AddReadableLogging_LetsConfigurationOverrideTheDefaults() + { + using var provider = BuildProvider(new Dictionary + { + ["Serilog:MinimumLevel:Default"] = "Debug", + ["Serilog:MinimumLevel:Override:Polly"] = "Information", + }); + var factory = provider.GetRequiredService(); + + factory.CreateLogger("Polly").IsEnabled(LogLevel.Information).Should().BeTrue(); + factory.CreateLogger("Some.Application.Handler").IsEnabled(LogLevel.Debug).Should().BeTrue(); + } + + [Fact] + public void AddReadableLogging_LetsConfigurationAddCategories() + { + using var provider = BuildProvider(new Dictionary + { + ["Serilog:MinimumLevel:Override:Aspire.Hosting.Dcp"] = "Warning", + }); + var logger = provider.GetRequiredService().CreateLogger("Aspire.Hosting.Dcp.Process"); + + logger.IsEnabled(LogLevel.Information).Should().BeFalse(); + } + + [Fact] + public void AddReadableLogging_DoesNotReplaceTheStaticLogger() + { + using var provider = BuildProvider(); + + provider.GetRequiredService().Should().NotBeNull(); + Log.Logger.Should().BeSameAs(Serilog.Core.Logger.None); + } + + [Fact] + public void AddReadableLogging_WithAnOtlpEndpoint_BuildsTheExportingLogger() + { + using var provider = BuildProvider(new Dictionary + { + ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://localhost:4317", + }); + + provider.GetRequiredService().Should().NotBeNull(); + } + + private static ServiceProvider BuildProvider(Dictionary? settings = null) + { + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(settings ?? []) + .Build(); + var environment = Substitute.For(); + environment.EnvironmentName.Returns(Environments.Production); + + return new ServiceCollection() + .AddReadableLogging(configuration, environment) + .BuildServiceProvider(); + } +} diff --git a/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs b/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs new file mode 100644 index 00000000..be177442 --- /dev/null +++ b/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs @@ -0,0 +1,135 @@ +using Microsoft.AspNetCore.Builder; +using Microsoft.AspNetCore.Hosting; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Http.Features; +using Microsoft.Extensions.DependencyInjection; +using Serilog; +using Serilog.Events; +using Serilog.Extensions.Hosting; + +namespace Admin.Logging.Tests; + +public class RequestLoggingTests +{ + private readonly CollectingSink _sink = new(); + + [Fact] + public async Task AddRequestLogging_LogsOneInformationEventPerRequestAndRunsTheApplicationPipeline() + { + var innerRan = false; + + await SendAsync("/api/v1/tags", context => + { + innerRan = true; + context.Response.StatusCode = StatusCodes.Status200OK; + return Task.CompletedTask; + }); + + innerRan.Should().BeTrue(); + var logged = _sink.Events.Should().ContainSingle().Subject; + logged.Level.Should().Be(LogEventLevel.Information); + Property(logged, "RequestMethod").Should().Be("GET"); + Property(logged, "RequestPath").Should().Be("/api/v1/tags"); + Property(logged, "StatusCode").Should().Be(200); + } + + [Fact] + public async Task AddRequestLogging_StripsControlCharactersFromTheLoggedPath() + { + await SendAsync("/api/v1/x\nFORGED ERR line\u001b[31m", _ => Task.CompletedTask); + + var path = (string)Property(_sink.Events.Single(), "RequestPath")!; + path.Should().Be("/api/v1/x_FORGED ERR line_[31m"); + } + + [Theory] + [InlineData("/health")] + [InlineData("/alive")] + [InlineData("/health/ready")] + public async Task AddRequestLogging_LogsQuietPathsBelowInformation(string path) + { + await SendAsync(path, _ => Task.CompletedTask, quietPaths: ["/health", "/alive"]); + + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Verbose); + } + + [Fact] + public async Task AddRequestLogging_LogsAFileServedWithoutAnEndpointBelowInformation() + { + await SendAsync("/js/login.js", _ => Task.CompletedTask, matchesEndpoint: false); + + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Verbose); + } + + [Fact] + public async Task AddRequestLogging_LogsARequestNoEndpointAnsweredWithAnErrorStatusAtInformation() + { + await SendAsync("/nao-existe", context => + { + context.Response.StatusCode = StatusCodes.Status404NotFound; + return Task.CompletedTask; + }, matchesEndpoint: false); + + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Information); + } + + [Fact] + public async Task AddRequestLogging_LogsAServerErrorResponseAsAnError() + { + await SendAsync("/api/v1/tags", context => + { + context.Response.StatusCode = StatusCodes.Status500InternalServerError; + return Task.CompletedTask; + }); + + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Error); + } + + [Fact] + public async Task AddRequestLogging_LogsAnUnhandledExceptionAsAnErrorAndRethrowsIt() + { + var send = () => SendAsync("/api/v1/tags", _ => throw new InvalidOperationException("boom")); + + await send.Should().ThrowAsync(); + var logged = _sink.Events.Should().ContainSingle().Subject; + logged.Level.Should().Be(LogEventLevel.Error); + logged.Exception.Should().BeOfType(); + } + + private async Task SendAsync( + string path, + RequestDelegate inner, + string[]? quietPaths = null, + bool matchesEndpoint = true) + { + var logger = new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(_sink) + .CreateLogger(); + var services = new ServiceCollection() + .AddSingleton(logger) + .AddSingleton(new DiagnosticContext(logger)) + .AddRequestLogging(quietPaths ?? []); + using var provider = services.BuildServiceProvider(); + + var app = new ApplicationBuilder(provider); + provider.GetRequiredService().Configure(builder => builder.Run(inner))(app); + + var context = new DefaultHttpContext { RequestServices = provider }; + context.Request.Method = HttpMethods.Get; + context.Request.Path = path; + context.Features.GetRequiredFeature().RawTarget = path; + + if (matchesEndpoint) + { + context.SetEndpoint(new Endpoint(_ => Task.CompletedTask, new EndpointMetadataCollection(), "test")); + } + + await app.Build()(context); + } + + private static object? Property(LogEvent logEvent, string name) + { + return ((ScalarValue)logEvent.Properties[name]).Value; + } +} diff --git a/backend/shared/Admin.Logging.Tests/TestSinks.cs b/backend/shared/Admin.Logging.Tests/TestSinks.cs new file mode 100644 index 00000000..f9716bfd --- /dev/null +++ b/backend/shared/Admin.Logging.Tests/TestSinks.cs @@ -0,0 +1,32 @@ +using Serilog.Core; +using Serilog.Events; +using Serilog.Formatting; + +namespace Admin.Logging.Tests; + +internal sealed class CollectingSink : ILogEventSink +{ + public List Events { get; } = []; + + public void Emit(LogEvent logEvent) + { + Events.Add(logEvent); + } +} + +internal sealed class FormattingSink : ILogEventSink +{ + private readonly ITextFormatter _formatter; + private readonly TextWriter _output; + + public FormattingSink(ITextFormatter formatter, TextWriter output) + { + _formatter = formatter; + _output = output; + } + + public void Emit(LogEvent logEvent) + { + _formatter.Format(logEvent, _output); + } +} diff --git a/backend/shared/Admin.Logging/Admin.Logging.csproj b/backend/shared/Admin.Logging/Admin.Logging.csproj new file mode 100644 index 00000000..3be63f42 --- /dev/null +++ b/backend/shared/Admin.Logging/Admin.Logging.csproj @@ -0,0 +1,26 @@ + + + + net10.0 + enable + enable + + + + + + + + + + + + + + + + + + diff --git a/backend/shared/Admin.Logging/ReadableConsole.cs b/backend/shared/Admin.Logging/ReadableConsole.cs new file mode 100644 index 00000000..ecf4596b --- /dev/null +++ b/backend/shared/Admin.Logging/ReadableConsole.cs @@ -0,0 +1,44 @@ +using System.Globalization; +using Serilog.Formatting; +using Serilog.Templates; +using Serilog.Templates.Themes; + +namespace Admin.Logging; + +internal static class ReadableConsole +{ + private const string Template = + "[{@t:HH:mm:ss} {@l:u3}]" + + "{#if SourceContext is not null} {Substring(SourceContext, LastIndexOf(SourceContext, '.') + 1)}:{#end}" + + " {@m}\n{@x}"; + + public static ITextFormatter CreateFormatter(bool colors) + { + var theme = colors ? TemplateTheme.Code : null; + + return new ExpressionTemplate( + Template, + CultureInfo.InvariantCulture, + theme: theme, + applyThemeWhenOutputIsRedirected: true); + } + + public static bool ShouldUseColors( + bool isDevelopment, + bool noColorRequested, + bool outputRedirected, + bool colorWhenRedirected) + { + if (!isDevelopment) + { + return false; + } + + if (noColorRequested) + { + return false; + } + + return colorWhenRedirected || !outputRedirected; + } +} diff --git a/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs b/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs new file mode 100644 index 00000000..b837e0a8 --- /dev/null +++ b/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs @@ -0,0 +1,65 @@ +using System.Globalization; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Serilog; +using Serilog.Events; + +namespace Admin.Logging; + +public static class ReadableLoggingExtensions +{ + private const string OtlpEndpointKey = "OTEL_EXPORTER_OTLP_ENDPOINT"; + + private static readonly string[] QuietCategories = + [ + "Microsoft.AspNetCore", + "Microsoft.EntityFrameworkCore.Database.Command", + "System.Net.Http.HttpClient", + "Polly", + ]; + + public static IServiceCollection AddReadableLogging( + this IServiceCollection services, + IConfiguration configuration, + IHostEnvironment environment, + bool colorWhenRedirected = false) + { + var colors = ReadableConsole.ShouldUseColors( + environment.IsDevelopment(), + noColorRequested: !string.IsNullOrEmpty(Environment.GetEnvironmentVariable("NO_COLOR")), + outputRedirected: Console.IsOutputRedirected, + colorWhenRedirected); + var exportToOtlp = !string.IsNullOrWhiteSpace(configuration[OtlpEndpointKey]); + + services.AddSerilog( + logger => Configure(logger, configuration, colors, exportToOtlp), + preserveStaticLogger: true); + + return services; + } + + private static void Configure( + LoggerConfiguration logger, + IConfiguration configuration, + bool colors, + bool exportToOtlp) + { + logger.MinimumLevel.Information(); + + foreach (var category in QuietCategories) + { + logger.MinimumLevel.Override(category, LogEventLevel.Warning); + } + + logger + .ReadFrom.Configuration(configuration) + .Enrich.FromLogContext() + .WriteTo.Console(ReadableConsole.CreateFormatter(colors)); + + if (exportToOtlp) + { + logger.WriteTo.OpenTelemetry(options => options.FormatProvider = CultureInfo.InvariantCulture); + } + } +} diff --git a/backend/shared/Admin.Logging/RequestLoggingExtensions.cs b/backend/shared/Admin.Logging/RequestLoggingExtensions.cs new file mode 100644 index 00000000..40bcf3a6 --- /dev/null +++ b/backend/shared/Admin.Logging/RequestLoggingExtensions.cs @@ -0,0 +1,16 @@ +using Microsoft.AspNetCore.Hosting; +using Microsoft.Extensions.DependencyInjection; + +namespace Admin.Logging; + +public static class RequestLoggingExtensions +{ + public static IServiceCollection AddRequestLogging(this IServiceCollection services, params string[] quietPaths) + { + services.AddTransient(provider => new RequestLoggingStartupFilter( + provider.GetRequiredService(), + quietPaths)); + + return services; + } +} diff --git a/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs b/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs new file mode 100644 index 00000000..43354c2e --- /dev/null +++ b/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs @@ -0,0 +1,82 @@ +using Microsoft.AspNetCore.Builder; +using Microsoft.AspNetCore.Hosting; +using Microsoft.AspNetCore.Http; +using Serilog; +using Serilog.Events; + +namespace Admin.Logging; + +internal sealed class RequestLoggingStartupFilter : IStartupFilter +{ + private readonly Serilog.ILogger _logger; + private readonly string[] _quietPaths; + + public RequestLoggingStartupFilter(Serilog.ILogger logger, string[] quietPaths) + { + _logger = logger; + _quietPaths = quietPaths; + } + + public Action Configure(Action next) + { + return app => + { + app.UseSerilogRequestLogging(options => + { + options.Logger = _logger; + options.GetLevel = GetLevel; + options.GetMessageTemplateProperties = GetMessageTemplateProperties; + }); + + next(app); + }; + } + + internal LogEventLevel GetLevel(HttpContext context, double elapsedMilliseconds, Exception? exception) + { + if (IsQuiet(context.Request.Path)) + { + return LogEventLevel.Verbose; + } + + if (exception is not null || context.Response.StatusCode >= StatusCodes.Status500InternalServerError) + { + return LogEventLevel.Error; + } + + if (IsStaticFile(context)) + { + return LogEventLevel.Verbose; + } + + return LogEventLevel.Information; + } + + internal static IEnumerable GetMessageTemplateProperties( + HttpContext context, + string path, + double elapsedMilliseconds, + int statusCode) + { + yield return new LogEventProperty("RequestMethod", new ScalarValue(context.Request.Method)); + yield return new LogEventProperty("RequestPath", new ScalarValue(SanitizeForLog(path))); + yield return new LogEventProperty("StatusCode", new ScalarValue(statusCode)); + yield return new LogEventProperty("Elapsed", new ScalarValue(elapsedMilliseconds)); + } + + // The decoded request path is attacker-controlled - a %0A in it would forge a log line (CWE-117). + internal static string SanitizeForLog(string value) + { + return string.Concat(value.Select(character => char.IsControl(character) ? '_' : character)); + } + + private static bool IsStaticFile(HttpContext context) + { + return context.GetEndpoint() is null && context.Response.StatusCode < StatusCodes.Status400BadRequest; + } + + private bool IsQuiet(PathString path) + { + return _quietPaths.Any(quietPath => path.StartsWithSegments(quietPath)); + } +} diff --git a/docs/MONOREPO.md b/docs/MONOREPO.md index c53065d7..63602c71 100644 --- a/docs/MONOREPO.md +++ b/docs/MONOREPO.md @@ -7,9 +7,9 @@ admin/ ├── backend/ │ ├── AdminBackend.slnx .NET solution │ ├── AppHost/ .NET Aspire orchestrator — local dev only, see below -│ ├── ServiceDefaults/ shared OpenTelemetry/health-check/service-discovery wiring +│ ├── ServiceDefaults/ shared logging/OpenTelemetry/health-check/service-discovery wiring │ ├── shared/ cross-cutting infrastructure only — kernel, ASP.NET Core and EF -│ │ helpers, token validation (backend/docs/ARCHITECTURE.md §1) +│ │ helpers, token validation, logging (backend/docs/ARCHITECTURE.md §1) │ └── services/ │ ├── identity-service/ OIDC provider (OpenIddict), tenants, users, M2M tokens │ └── services-service/ the tenant's business context: what it offers and whom it serves diff --git a/docs/QUALITY.md b/docs/QUALITY.md index b0b1bf2b..03b0db7a 100644 --- a/docs/QUALITY.md +++ b/docs/QUALITY.md @@ -29,7 +29,9 @@ NuGet, pip, and the workflows' actions. assemblies each project references — **Domain + Application** — gated at 80% line coverage. `Admin.SharedKernel` is excluded from every _consuming_ service's gate (`Directory.Build.targets`) since it - has its own dedicated project (`Admin.SharedKernel.Tests`) and gate — + has its own dedicated project (`Admin.SharedKernel.Tests`) and gate, and + so does `Admin.Logging` (`Admin.Logging.Tests`, which never counts + toward a service's gate because no service test project references it) — counting it twice would let one hide behind the other's number (docs/adr/0005). `ServicesService.PersistenceTests` covers EF tenant assignment and filtering in memory (docs/adr/0019). There is no diff --git a/docs/adr/0054-serilog-readable-console-logging.md b/docs/adr/0054-serilog-readable-console-logging.md new file mode 100644 index 00000000..50dac038 --- /dev/null +++ b/docs/adr/0054-serilog-readable-console-logging.md @@ -0,0 +1,67 @@ +# ADR 0054 — Serilog is the logging pipeline of every .NET host, in one shared library + +Status: accepted (2026-10) + +## Context + +Logs came from the default Microsoft console provider plus the OpenTelemetry logging provider, configured separately +for each API (`appsettings.json`) and for the AppHost. The console showed two lines per event +(`info: Microsoft.Hosting.Lifetime[14]`, then the message), every EF Core command as a multi-line SQL block at +`Information`, five lines for one outgoing HTTP call (HttpClient handlers plus Polly), and nothing at all for a normal +request because `Microsoft.AspNetCore` is `Warning`. The signal was buried, and the AppHost looked different from the +services. + +## Decision + +`backend/shared/Admin.Logging` owns how a .NET process logs. Its callers are `ServiceDefaults` (so every service that +calls `AddServiceDefaults()`) and the AppHost; nothing else references it. Code keeps writing `ILogger` against +`Microsoft.Extensions.Logging.Abstractions`; Domain and Application never reference Serilog, and the static `Log` is +neither used nor replaced ([0018](0018-shared-kernel-aspnetcore-split.md)). + +A new service gets all of the following from `AddServiceDefaults()`, with no `Program.cs` line and no settings block: + +- **One console format**, `[HH:mm:ss LVL] ShortContext: message`, then the exception block. `ShortContext` is the last + segment of the logger category. Culture is invariant (`35.8 ms`, not `35,8 ms`), in the console and in the OTLP body. + The time is the host's local time: [0045](0045-backend-works-in-utc.md) is about domain and persistence instants, and + the OTLP export carries absolute ones. `UtcDateTime(@t)` in the template flips it. +- **Colors** only in `Development`, never with `NO_COLOR`. A service passes `colorWhenRedirected` because the Aspire + dashboard renders ANSI although stdout is redirected; the AppHost does not, since under `aspire run` the CLI captures + its output to a file. +- **Levels in code**: `Information`, with `Microsoft.AspNetCore`, `Microsoft.EntityFrameworkCore.Database.Command`, + `System.Net.Http.HttpClient` and `Polly` at `Warning`. `Serilog:MinimumLevel` in configuration overrides or extends + that per host (the AppHost quiets `Aspire.Hosting.Dcp` there). `OpenIddict` stays at `Information` on purpose: it + reports rejected token and authorization requests there. `Logging:LogLevel` is no longer read. +- **Structured export** through `Serilog.Sinks.OpenTelemetry`, only when `OTEL_EXPORTER_OTLP_ENDPOINT` is set. It reads + the `OTEL_*` variables Aspire injects, so log-to-trace correlation and the resource name need no code. +- **One line per request**, from an `IStartupFilter` that puts `UseSerilogRequestLogging` outside the application's own + middleware, so a 500 turned into a problem response by `UseExceptionHandler` is still logged with its status. + `/health` and `/alive` (passed in by ServiceDefaults) and files served without an endpoint are `Verbose`. The query + string is never logged, and control characters are stripped from the path, as `GenericExceptionHandler` already does + for its own line (CWE-117). + +## Tried and set aside + +- **First version**: the template compiled into the AppHost as a linked file, `app.UseRequestLogging()` in each + `Program.cs`, and the same `Serilog` block copied into three `appsettings.json`. It worked, but a new service had to + remember all three, and the AppHost's copy of the format could drift. That is what this library replaces. +- A template that escapes CR/LF in every message: `Replace` does not exist in Serilog.Expressions 5.0. A sink wrapper + would do it, but one request path is the only attacker-controlled value the new code adds. +- The default `ExpressionTemplate` theme: it silently drops the colors when stdout is redirected, which is always the + case under Aspire. +- Keeping the OpenTelemetry logging provider next to Serilog (`writeToProviders`): two level configurations for one + stream. +- A JSON console outside Development, a file sink, a bootstrap logger with a top-level `try`/`catch`: nothing needs them + yet, and OTLP already carries the structured form. +- The Python assistant service: Serilog is .NET. It keeps its own logging. + +## Consequences + +- To see SQL again, set `Microsoft.EntityFrameworkCore.Database.Command` to `Information` under + `Serilog:MinimumLevel:Override` in `appsettings.Development.json`. +- The control-character guard covers the request line and `GenericExceptionHandler`; any other template value is + written as-is. Today's application log sites log constraint names, error codes and enum kinds, never request input, + so nothing else needs it yet. A new log site that puts request input in a message must sanitize it, or the guard + moves to a sink wrapper. +- A request answered without a matched endpoint and with a 2xx/3xx status is treated as a static file. A redirect from + `UseHttpsRedirection` is therefore `Verbose` too. +- `Admin.Logging` has its own test project and coverage gate, like `Admin.SharedKernel`. diff --git a/docs/adr/README.md b/docs/adr/README.md index 73d1c2a1..878507a4 100644 --- a/docs/adr/README.md +++ b/docs/adr/README.md @@ -17,6 +17,7 @@ superseded is historical evidence, not current implementation guidance. | Database bootstrap | 0025 as narrowed by 0027, plus 0027/0028 | | Git workflow | 0021 as amended by 0030/0031 | | Toolchain compatibility | 0032, 0050 | +| Logging and telemetry | 0054 | | admin-frontend architecture | 0033, 0034, 0035, 0036, 0037, 0038 | | admin-frontend UI foundation | 0039, 0040, 0043 | | AI agent instruction files | 0041 | @@ -74,4 +75,4 @@ instruction files reinstated · 0042 widgets layer and layer-boundaries lint rul (proposed) · 0044 clients aggregate, uniqueness rules and conflict contract · 0045 backend works in UTC only · 0046 separate soft-delete and tenant query filters · 0048 database failures are generic to the user · 0049 conventions for new backend slices · 0050 xUnit v3 on VSTest and the Aspire CLI bundle · -0051 camelCase error keys on the wire. +0051 camelCase error keys on the wire · 0054 Serilog logging pipeline. From a3f638346e3b1a291ba5a059ac1d22de901316fb Mon Sep 17 00:00:00 2001 From: Everton William Thoele Schuster Date: Mon, 5 Oct 2026 14:04:11 -0300 Subject: [PATCH 2/4] fix(backend): mostrar a categoria completa do logger no console MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit O formato cortava a categoria no último segmento, então Microsoft.Hosting.Lifetime aparecia como "Lifetime" e Microsoft.EntityFrameworkCore.Migrations como "Migrations": nomes que não são classes e que o console padrão mostrava inteiros. Agora a categoria sai completa; para um ILogger é o nome completo da classe. Teste novo prova que um ILogger mostra a classe de verdade. ADR 0054 atualizada. Co-Authored-By: Claude Sonnet 5.5 --- .../ReadableConsoleTests.cs | 24 +++++++++++++++---- .../shared/Admin.Logging/ReadableConsole.cs | 2 +- .../0054-serilog-readable-console-logging.md | 6 +++-- 3 files changed, 25 insertions(+), 7 deletions(-) diff --git a/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs b/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs index 280f9e90..464ac634 100644 --- a/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs +++ b/backend/shared/Admin.Logging.Tests/ReadableConsoleTests.cs @@ -1,18 +1,34 @@ using System.Globalization; +using Microsoft.Extensions.Logging; using Serilog; +using Serilog.Extensions.Logging; namespace Admin.Logging.Tests; +internal sealed class SampleHandler; + public class ReadableConsoleTests { [Fact] - public void Format_ShortensTheSourceContextToItsLastSegment() + public void Format_ShowsTheFullSourceContext() { var output = Render(colors: false, logger => logger - .ForContext("SourceContext", "ServicesService.Application.Clients.CreateClientCommandHandler") - .Information("Client {ClientId} created", 42)); + .ForContext("SourceContext", "Microsoft.Hosting.Lifetime") + .Information("Now listening on: {Address}", "http://localhost:5080")); + + output.Should().MatchRegex(@"^\[\d{2}:\d{2}:\d{2} INF\] Microsoft\.Hosting\.Lifetime: Now listening on: http://localhost:5080\n$"); + } + + [Fact] + public void Format_ForAnILoggerOfT_ShowsTheFullNameOfThatClass() + { + var output = Render(colors: false, logger => + { + using var factory = new SerilogLoggerFactory(logger); + factory.CreateLogger().LogInformation("Client {ClientId} created", 42); + }); - output.Should().MatchRegex(@"^\[\d{2}:\d{2}:\d{2} INF\] CreateClientCommandHandler: Client 42 created\n$"); + output.Should().MatchRegex(@"^\[\d{2}:\d{2}:\d{2} INF\] Admin\.Logging\.Tests\.SampleHandler: Client 42 created\n$"); } [Fact] diff --git a/backend/shared/Admin.Logging/ReadableConsole.cs b/backend/shared/Admin.Logging/ReadableConsole.cs index ecf4596b..6eb859dd 100644 --- a/backend/shared/Admin.Logging/ReadableConsole.cs +++ b/backend/shared/Admin.Logging/ReadableConsole.cs @@ -9,7 +9,7 @@ internal static class ReadableConsole { private const string Template = "[{@t:HH:mm:ss} {@l:u3}]" + - "{#if SourceContext is not null} {Substring(SourceContext, LastIndexOf(SourceContext, '.') + 1)}:{#end}" + + "{#if SourceContext is not null} {SourceContext}:{#end}" + " {@m}\n{@x}"; public static ITextFormatter CreateFormatter(bool colors) diff --git a/docs/adr/0054-serilog-readable-console-logging.md b/docs/adr/0054-serilog-readable-console-logging.md index 50dac038..99a35310 100644 --- a/docs/adr/0054-serilog-readable-console-logging.md +++ b/docs/adr/0054-serilog-readable-console-logging.md @@ -20,8 +20,10 @@ neither used nor replaced ([0018](0018-shared-kernel-aspnetcore-split.md)). A new service gets all of the following from `AddServiceDefaults()`, with no `Program.cs` line and no settings block: -- **One console format**, `[HH:mm:ss LVL] ShortContext: message`, then the exception block. `ShortContext` is the last - segment of the logger category. Culture is invariant (`35.8 ms`, not `35,8 ms`), in the console and in the OTLP body. +- **One console format**, `[HH:mm:ss LVL] Category: message`, then the exception block. The category is written in full + (`ServicesService.Application.Clients.CreateClient.CreateClientCommandHandler` for an `ILogger`): the first version + cut it to its last segment, which turned `Microsoft.Hosting.Lifetime` into a misleading `Lifetime`. Culture is + invariant (`35.8 ms`, not `35,8 ms`), in the console and in the OTLP body. The time is the host's local time: [0045](0045-backend-works-in-utc.md) is about domain and persistence instants, and the OTLP export carries absolute ones. `UtcDateTime(@t)` in the template flips it. - **Colors** only in `Development`, never with `NO_COLOR`. A service passes `colorWhenRedirected` because the Aspire From 61a1794f4b516978b47a94dea522575db8bf8f8e Mon Sep 17 00:00:00 2001 From: Everton William Thoele Schuster Date: Mon, 5 Oct 2026 14:13:25 -0300 Subject: [PATCH 3/4] =?UTF-8?q?feat(identity):=20filtrar=20o=20ru=C3=ADdo?= =?UTF-8?q?=20de=20request/response=20do=20OpenIddict=20nos=20logs?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit O OpenIddict registra em Information, na mesma categoria, tanto as cópias completas de cada request e response (discovery, JWKS, tokens) quanto as rejeições de autenticação. Baixar o nível esconderia o motivo de cada falha de login, então o identity-service descarta só o ruído por Serilog:Filter (was successfully extracted/validated/returned, matched a server endpoint) e mantém as rejeições. Numa sequência de 4 requisições de token e autorização o log foi de 136 para 14 linhas. Se o OpenIddict reescrever uma mensagem, o ruído volta; nada some. Teste novo garante que Serilog:Filter da configuração é respeitado pela Admin.Logging. ADR 0054 e ARCHITECTURE §8 atualizados. Co-Authored-By: Claude Sonnet 5.5 --- backend/docs/ARCHITECTURE.md | 3 +- .../IdentityService.Api/appsettings.json | 10 +++++++ .../ReadableLoggingExtensionsTests.cs | 28 +++++++++++++++++++ .../0054-serilog-readable-console-logging.md | 8 ++++-- 4 files changed, 46 insertions(+), 3 deletions(-) diff --git a/backend/docs/ARCHITECTURE.md b/backend/docs/ARCHITECTURE.md index 29c162ee..5750a720 100644 --- a/backend/docs/ARCHITECTURE.md +++ b/backend/docs/ARCHITECTURE.md @@ -362,7 +362,8 @@ Inject `ILogger` and write a message template with named placeholders, never the pipeline behind it, owned by `Admin.Logging` and brought in by `AddServiceDefaults()` ([0054](../../docs/adr/0054-serilog-readable-console-logging.md)): a service configures nothing. Domain and Application stay on `Microsoft.Extensions.Logging.Abstractions` and nothing calls the static `Log`. The default levels live in -`Admin.Logging`; a host that needs another level sets it under `Serilog:MinimumLevel` in its `appsettings.json` +`Admin.Logging`; a host that needs another level sets it under `Serilog:MinimumLevel` in its `appsettings.json`, and drops a +noisy message by text with `Serilog:Filter` (identity-service does, for OpenIddict's request dumps) (`Logging:LogLevel` is ignored). A message carries constraint names, codes and ids, not request input; when it must, strip control characters first (CWE-117), as `GenericExceptionHandler` and the request line do. diff --git a/backend/services/identity-service/IdentityService.Api/appsettings.json b/backend/services/identity-service/IdentityService.Api/appsettings.json index 05348358..95208a29 100644 --- a/backend/services/identity-service/IdentityService.Api/appsettings.json +++ b/backend/services/identity-service/IdentityService.Api/appsettings.json @@ -1,4 +1,14 @@ { + "Serilog": { + "Filter": [ + { + "Name": "ByExcluding", + "Args": { + "expression": "StartsWith(SourceContext, 'OpenIddict') and (@mt like '%was successfully%' or @mt like 'The request URI matched%')" + } + } + ] + }, "AllowedHosts": "*", "DatabaseBootstrap": { "RunOnStartup": false diff --git a/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs index 81723d64..7c4a4569 100644 --- a/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs +++ b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs @@ -69,6 +69,34 @@ public void AddReadableLogging_LetsConfigurationAddCategories() logger.IsEnabled(LogLevel.Information).Should().BeFalse(); } + [Fact] + public void AddReadableLogging_HonorsFiltersFromConfiguration() + { + var captured = new StringWriter(); + var previous = Console.Out; + Console.SetOut(captured); + + try + { + using var provider = BuildProvider(new Dictionary + { + ["Serilog:Filter:0:Name"] = "ByExcluding", + ["Serilog:Filter:0:Args:expression"] = "@mt like '%was successfully%'", + }); + var logger = provider.GetRequiredService().CreateLogger("OpenIddict.Server.Dispatcher"); + + logger.LogInformation("The request was successfully extracted"); + logger.LogInformation("The request was rejected because invalid scopes were specified"); + } + finally + { + Console.SetOut(previous); + } + + captured.ToString().Should().Contain("rejected because invalid scopes"); + captured.ToString().Should().NotContain("successfully extracted"); + } + [Fact] public void AddReadableLogging_DoesNotReplaceTheStaticLogger() { diff --git a/docs/adr/0054-serilog-readable-console-logging.md b/docs/adr/0054-serilog-readable-console-logging.md index 99a35310..faafd09e 100644 --- a/docs/adr/0054-serilog-readable-console-logging.md +++ b/docs/adr/0054-serilog-readable-console-logging.md @@ -31,8 +31,12 @@ A new service gets all of the following from `AddServiceDefaults()`, with no `Pr its output to a file. - **Levels in code**: `Information`, with `Microsoft.AspNetCore`, `Microsoft.EntityFrameworkCore.Database.Command`, `System.Net.Http.HttpClient` and `Polly` at `Warning`. `Serilog:MinimumLevel` in configuration overrides or extends - that per host (the AppHost quiets `Aspire.Hosting.Dcp` there). `OpenIddict` stays at `Information` on purpose: it - reports rejected token and authorization requests there. `Logging:LogLevel` is no longer read. + that per host (the AppHost quiets `Aspire.Hosting.Dcp` there), and `Serilog:Filter` drops messages by text. + `OpenIddict` stays at `Information` on purpose: it reports rejected token and authorization requests there, in the + same category as its request and response dumps. identity-service therefore keeps the level and filters the dumps + (`was successfully extracted/validated/returned`, `matched a server endpoint`): a token request goes from about + twenty lines to the request line, plus the reason when it is rejected. If OpenIddict rewords a message the noise + comes back; nothing is hidden. `Logging:LogLevel` is no longer read. - **Structured export** through `Serilog.Sinks.OpenTelemetry`, only when `OTEL_EXPORTER_OTLP_ENDPOINT` is set. It reads the `OTEL_*` variables Aspire injects, so log-to-trace correlation and the resource name need no code. - **One line per request**, from an `IStartupFilter` that puts `UseSerilogRequestLogging` outside the application's own From fe88b7522640ae38a4c9924cf09c52bec31bdf1f Mon Sep 17 00:00:00 2001 From: Everton William Thoele Schuster Date: Mon, 5 Oct 2026 14:18:15 -0300 Subject: [PATCH 4/4] =?UTF-8?q?fix(backend):=20endpoint=20OTLP=20vindo=20d?= =?UTF-8?q?a=20configura=C3=A7=C3=A3o=20e=20falhas=20em=20/health=20sempre?= =?UTF-8?q?=20logadas?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Duas correções da revisão do PR: - O sink OTLP só enxerga variáveis de ambiente. Se OTEL_EXPORTER_OTLP_ENDPOINT vinha de outra fonte do IConfiguration, o export era habilitado mas ficava no localhost:4317. Agora o endpoint é passado ao sink a partir da configuração. - /health e /alive em Verbose eram avaliados antes das falhas, então um 5xx ou uma exceção numa sonda era descartado pelo nível mínimo. Falhas agora são checadas primeiro; sondas bem-sucedidas continuam em Verbose. Testes novos: endpoint da configuração, sonda com 503 e sonda com exceção. ADR 0054 atualizada. Co-Authored-By: Claude Sonnet 5.5 --- .../ReadableLoggingExtensionsTests.cs | 21 ++++++++++++++++- .../RequestLoggingTests.cs | 23 +++++++++++++++++++ .../ReadableLoggingExtensions.cs | 9 +++++++- .../RequestLoggingStartupFilter.cs | 8 +++---- .../0054-serilog-readable-console-logging.md | 3 ++- 5 files changed, 57 insertions(+), 7 deletions(-) diff --git a/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs index 7c4a4569..81e23512 100644 --- a/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs +++ b/backend/shared/Admin.Logging.Tests/ReadableLoggingExtensionsTests.cs @@ -1,9 +1,11 @@ +using System.Globalization; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; using NSubstitute; using Serilog; +using Serilog.Sinks.OpenTelemetry; namespace Admin.Logging.Tests; @@ -111,12 +113,29 @@ public void AddReadableLogging_WithAnOtlpEndpoint_BuildsTheExportingLogger() { using var provider = BuildProvider(new Dictionary { - ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://localhost:4317", + ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://collector.internal:4317", }); provider.GetRequiredService().Should().NotBeNull(); } + [Fact] + public void ConfigureOtlp_UsesTheEndpointFromConfigurationAndTheInvariantCulture() + { + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary + { + ["OTEL_EXPORTER_OTLP_ENDPOINT"] = "http://collector.internal:4317", + }) + .Build(); + var options = new OpenTelemetrySinkOptions(); + + ReadableLoggingExtensions.ConfigureOtlp(options, configuration); + + options.Endpoint.Should().Be("http://collector.internal:4317"); + options.FormatProvider.Should().BeSameAs(CultureInfo.InvariantCulture); + } + private static ServiceProvider BuildProvider(Dictionary? settings = null) { var configuration = new ConfigurationBuilder() diff --git a/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs b/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs index be177442..6ca39699 100644 --- a/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs +++ b/backend/shared/Admin.Logging.Tests/RequestLoggingTests.cs @@ -53,6 +53,29 @@ public async Task AddRequestLogging_LogsQuietPathsBelowInformation(string path) _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Verbose); } + [Theory] + [InlineData("/health")] + [InlineData("/alive")] + public async Task AddRequestLogging_LogsAFailingQuietPathAsAnError(string path) + { + await SendAsync(path, context => + { + context.Response.StatusCode = StatusCodes.Status503ServiceUnavailable; + return Task.CompletedTask; + }, quietPaths: ["/health", "/alive"]); + + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Error); + } + + [Fact] + public async Task AddRequestLogging_LogsAnExceptionOnAQuietPathAsAnErrorAndRethrowsIt() + { + var send = () => SendAsync("/health", _ => throw new InvalidOperationException("boom"), quietPaths: ["/health"]); + + await send.Should().ThrowAsync(); + _sink.Events.Should().ContainSingle().Which.Level.Should().Be(LogEventLevel.Error); + } + [Fact] public async Task AddRequestLogging_LogsAFileServedWithoutAnEndpointBelowInformation() { diff --git a/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs b/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs index b837e0a8..27d4f11a 100644 --- a/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs +++ b/backend/shared/Admin.Logging/ReadableLoggingExtensions.cs @@ -4,6 +4,7 @@ using Microsoft.Extensions.Hosting; using Serilog; using Serilog.Events; +using Serilog.Sinks.OpenTelemetry; namespace Admin.Logging; @@ -59,7 +60,13 @@ private static void Configure( if (exportToOtlp) { - logger.WriteTo.OpenTelemetry(options => options.FormatProvider = CultureInfo.InvariantCulture); + logger.WriteTo.OpenTelemetry(options => ConfigureOtlp(options, configuration)); } } + + internal static void ConfigureOtlp(OpenTelemetrySinkOptions options, IConfiguration configuration) + { + options.Endpoint = configuration[OtlpEndpointKey]!; + options.FormatProvider = CultureInfo.InvariantCulture; + } } diff --git a/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs b/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs index 43354c2e..03ec25c4 100644 --- a/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs +++ b/backend/shared/Admin.Logging/RequestLoggingStartupFilter.cs @@ -34,14 +34,14 @@ public Action Configure(Action next) internal LogEventLevel GetLevel(HttpContext context, double elapsedMilliseconds, Exception? exception) { - if (IsQuiet(context.Request.Path)) + if (exception is not null || context.Response.StatusCode >= StatusCodes.Status500InternalServerError) { - return LogEventLevel.Verbose; + return LogEventLevel.Error; } - if (exception is not null || context.Response.StatusCode >= StatusCodes.Status500InternalServerError) + if (IsQuiet(context.Request.Path)) { - return LogEventLevel.Error; + return LogEventLevel.Verbose; } if (IsStaticFile(context)) diff --git a/docs/adr/0054-serilog-readable-console-logging.md b/docs/adr/0054-serilog-readable-console-logging.md index faafd09e..90d0bf44 100644 --- a/docs/adr/0054-serilog-readable-console-logging.md +++ b/docs/adr/0054-serilog-readable-console-logging.md @@ -41,7 +41,8 @@ A new service gets all of the following from `AddServiceDefaults()`, with no `Pr the `OTEL_*` variables Aspire injects, so log-to-trace correlation and the resource name need no code. - **One line per request**, from an `IStartupFilter` that puts `UseSerilogRequestLogging` outside the application's own middleware, so a 500 turned into a problem response by `UseExceptionHandler` is still logged with its status. - `/health` and `/alive` (passed in by ServiceDefaults) and files served without an endpoint are `Verbose`. The query + `/health` and `/alive` (passed in by ServiceDefaults) and files served without an endpoint are `Verbose`, unless the + request throws or answers 5xx: a failing probe is logged as an error like any other request. The query string is never logged, and control characters are stripped from the path, as `GenericExceptionHandler` already does for its own line (CWE-117).