diff --git a/.editorconfig b/.editorconfig new file mode 100644 index 0000000..00e56d3 --- /dev/null +++ b/.editorconfig @@ -0,0 +1,7 @@ +root = true + +[src/Tjidde.Logging/Extensions/MetricsLoggerExtensions.cs] +# These public extension methods intentionally forward the caller's message template and arguments to ILogger. +# LoggerMessage delegates require fixed templates and would change the API's intended behavior. +dotnet_diagnostic.CA1848.severity = none +dotnet_diagnostic.CA2254.severity = none diff --git a/.github/dependabot.yml b/.github/dependabot.yml index e41a488..3254518 100644 --- a/.github/dependabot.yml +++ b/.github/dependabot.yml @@ -1,14 +1,14 @@ version: 2 updates: + # Library and tests. - package-ecosystem: "nuget" - directory: "/" + directories: + - "/src/*" + - "/tests/*" schedule: interval: "weekly" groups: - microsoft-extensions: - patterns: - - "Microsoft.Extensions.*" test-packages: patterns: - "xunit*" @@ -17,11 +17,11 @@ updates: ignore: # The library (and the test project) reference Microsoft.Extensions.* with one major per # target framework on purpose: 7.0.x for net7.0, 8.0.x for net8.0, 9.0.x for net9.0 and - # 10.0.x for net10.0. A higher major does not support the older TFM (or would force - # consumers on that TFM onto a newer Microsoft.Extensions line), so only allow - # minor/patch updates within each major. Raise majors by hand when adding a new TFM. + # 10.0.x for net10.0, with deliberately low minimum versions in the library. Dependabot + # takes the highest version in a file as the current one and rewrites every occurrence, + # which collapses the per-TFM ItemGroups, so a semver-major ignore is not enough. + # The per-TFM versions are updated by hand. - dependency-name: "Microsoft.Extensions.*" - update-types: ["version-update:semver-major"] # net7.0 in the test project is pinned to the last releases that still support it: # Microsoft.NET.Test.Sdk 17.13.0 (17.14+ requires net8.0) and xunit.runner.visualstudio # 3.0.2 (3.1+ requires net8.0). The net8.0+ references are already on newer majors, so @@ -35,6 +35,21 @@ updates: - dependency-name: "xunit.runner.visualstudio" update-types: ["version-update:semver-major"] + # Samples and benchmarks: single TFM (net10.0), so all packages can follow the latest release. + - package-ecosystem: "nuget" + directories: + - "/samples/*" + - "/benchmarks/*" + schedule: + interval: "weekly" + groups: + microsoft-extensions: + patterns: + - "Microsoft.Extensions.*" + avalonia: + patterns: + - "Avalonia*" + - package-ecosystem: "github-actions" directory: "/" schedule: diff --git a/.github/workflows/publish.yml b/.github/workflows/publish.yml index 695f346..0773053 100644 --- a/.github/workflows/publish.yml +++ b/.github/workflows/publish.yml @@ -54,7 +54,7 @@ jobs: run: dotnet restore TjiddeLogger.sln - name: Build - run: dotnet build TjiddeLogger.sln --configuration Release --no-restore -p:Version=${{ steps.version.outputs.version }} -p:ContinuousIntegrationBuild=true + run: dotnet build TjiddeLogger.sln --configuration Release --no-restore -p:Version=${{ steps.version.outputs.version }} # Runs once per target framework (net7.0, net8.0, net9.0, net10.0) - name: Test diff --git a/.gitignore b/.gitignore index eaee47b..3a544f6 100644 --- a/.gitignore +++ b/.gitignore @@ -39,3 +39,9 @@ desktop.ini # Logs *.log + +# BenchmarkDotNet results +BenchmarkDotNet.Artifacts/ + +# Claude Code worktrees and local state +.claude/ diff --git a/CHANGELOG.md b/CHANGELOG.md index f23374c..6f7d7f8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,12 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and - `MaskedKeysStore`: a non-static, thread-safe `IMaskedKeysAccessor` with `Add`, `Remove`, `Clear` and `GetKeys` that returns immutable snapshots, and the builder extension `UseIsolatedMaskedKeys()`, which registers one store per host as the `IMaskedKeysAccessor` (replacing an earlier registration, in any order relative to `AddTjiddeLogger`). Inject `MaskedKeysStore` to add keys that apply immediately to that host's loggers only, so hosts and tests in one process no longer share runtime keys. The static `MaskedKeysContext` stays the default and now uses a `MaskedKeysStore` internally. The README, wikis and AI integration guide now recommend the accessors and DI for testable code and describe the static classes as the convenience variant. +- Sinks: the public `ILogSink` interface (namespace `Tjidde.Logging.Sinks`) receives every entry as an immutable `TjiddeLogEntry` with `Timestamp`, `Level`, `EventId`, `Category`, `ClassName`, `MethodName`, `Customer`, `Message`, `FormattedException`, `RenderedLine` (text or JSON), `OutputFormat` and `IsMetrics`; all text in it is masked. Register sinks with `AddTjiddeSink()`, `AddTjiddeSink(instance)` or `services.AddSingleton()`. Sinks are called synchronously on the logging thread; an exception in a sink is ignored and never affects logging, the console or other sinks, and entries logged from inside a sink are not dispatched again. New constructor overload `TjiddeLoggerProvider(..., TimeProvider, IEnumerable?)`. +- `InMemoryLogSink`: a built-in, thread-safe sink that keeps the newest `Capacity` entries (default 1000), with `GetSnapshot()`, `Count`, `Clear()` and the events `EntryAdded` and `Cleared`. Register it with `AddTjiddeInMemorySink(capacity)`. +- `TjiddeLoggerOptions.WriteToConsole` (default `true`): set to `false` to write only to the sinks. Applies immediately when the options reload. +- XML documentation for `TjiddeLogOutputFormat.Text` and `Json`. +- Samples: the Blazor, Avalonia and terminal samples use the built-in `InMemoryLogSink` instead of their own in-memory logger providers, recognize metrics entries by their event ID instead of the obsolete `Metrics` level, and log metrics with `LogMetrics`. The terminal sample turns the console off, so console output no longer draws over its UI. + ### Changed - Options changes now apply to existing loggers immediately, without a restart: the provider listens to `IOptionsMonitor.OnChange`, and `AddTjiddeLogger(IConfiguration)` / `AddTjiddeLogger(IConfigurationSection)` rebind the options when the configuration reloads (for example `appsettings.json` with `reloadOnChange`). Options, masker, exception formatter and OpenTelemetry fallback `ActivitySource` are replaced together, so a log call never mixes old and new settings; the previous `ActivitySource` is disposed. - `LogMetrics` now logs at `LogLevel.Information` with `MetricsEventId` instead of the custom level `(LogLevel)10`. Tjidde.Logging still shows these entries as `[METRICS]` and its own minimum level never drops them; other providers see a normal information entry. `LogMetrics(EventId, ...)` keeps the caller's event ID and only adds the name `Metrics` when it has none. @@ -20,6 +26,12 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and - `AddTjiddeLogger` registers `TjiddeLoggerProvider` through a factory, so the container never has to choose between its constructors. - `IsEnabled` caches the resolved minimum level per logger until the options change, instead of matching `CategoryMinimumLevels` on every call. +### Performance +Output is unchanged; see `benchmarks/README.md` for the measurements (new BenchmarkDotNet project `benchmarks/Tjidde.Logging.Benchmarks`). +- `SensitiveDataMasker.MaskMessage` skips the regular expressions of a key that does not occur in the text (case-insensitive ordinal check, on .NET 9+ one `SearchValues` scan for all keys). Text with non-ASCII characters and non-ASCII keys still always run the expressions, because those can match case-insensitively in ways an ordinal comparison does not. +- Fewer allocations per entry: the list of masked property names is only created when a property is masked, the property list is sized up front, the scopes are read in one pass (method name and scope texts together, without closures or LINQ), and the text line is written into one reused `StringBuilder` per thread instead of via intermediate strings. +- JSON output is written with a `Utf8JsonWriter` (one reused buffer per thread) instead of serializing two dictionaries, and string, `int`, `long` and `bool` property values are written directly instead of through a `JsonElement`. The JSON is byte for byte the same; when the writer fails, the previous serializer path is used. + ### Fixed - `LogMetrics` threw an `ArgumentOutOfRangeException` when another provider, such as the Microsoft console logger (`AddConsole()`), was also registered. - Logging no longer throws. A property value that cannot be serialized (unsupported type, throwing getter) falls back to its `ToString()`, or to `[unserializable: TypeName]` when that throws too; a value whose `ToString()` or enumeration throws no longer breaks the message (the template is used instead); a failing custom `IExceptionFormatter` falls back to exception type and message; scopes that throw are skipped; OpenTelemetry export failures are ignored. Any other failure while building the entry writes a minimal line with level, category, message and a note that rendering failed. diff --git a/Directory.Build.props b/Directory.Build.props new file mode 100644 index 0000000..ca7fa72 --- /dev/null +++ b/Directory.Build.props @@ -0,0 +1,11 @@ + + + false + + + + true + true + true + + diff --git a/README.md b/README.md index fc690a5..5d61511 100644 --- a/README.md +++ b/README.md @@ -1,5 +1,8 @@ # Tjidde.Logging +[![NuGet](https://img.shields.io/nuget/v/Tjidde.Logging.svg)](https://www.nuget.org/packages/Tjidde.Logging) +[![CI](https://github.com/tjidde-nl/TjiddeLogger/actions/workflows/ci.yml/badge.svg)](https://github.com/tjidde-nl/TjiddeLogger/actions/workflows/ci.yml) + A reusable NuGet package for standardized, structured logging in .NET applications. Integrates naturally with the Microsoft.Extensions.Logging pipeline. @@ -35,7 +38,7 @@ dotnet add package Tjidde.Logging Or via PackageReference: ```xml - + ``` --- @@ -116,7 +119,7 @@ CustomerContext.Set("AcmeCorp"); // Later in any service in the same async flow: _logger.LogInformation("Order placed successfully."); -// Output: 2024-03-17: 14:22:01: [INF] OrderService: AcmeCorp: Order placed successfully. +// Output: 2024-03-17: 14:22:01: [INFORMATION] Class=>OrderService: Client=>AcmeCorp: Order placed successfully. // Clear when done (optional — AsyncLocal is scoped to the flow): CustomerContext.Clear(); @@ -161,7 +164,7 @@ public class OrderService Output: ``` -2024-03-17: 14:22:01: [INF] OrderService: AcmeCorp: Placing order 42 +2024-03-17: 14:22:01: [INFORMATION] Class=>OrderService: Client=>AcmeCorp: Placing order 42 ``` ### Logging an exception @@ -179,18 +182,40 @@ catch (Exception ex) Output: ``` -2024-03-17: 14:22:01: [ERR] OrderService: AcmeCorp: Failed to process order 42 -Exception Type : System.InvalidOperationException -Message : Payment gateway timeout -Stack Trace : - at OrderService.ProcessPayment() in OrderService.cs:line 42 -Inner Exception: - -> Exception Type : System.TimeoutException - -> Message : The operation timed out +2024-03-17: 14:22:01: [ERROR] Class=>OrderService: Client=>AcmeCorp: Failed to process order 42 | Exception: [System.InvalidOperationException: Payment gateway timeout | StackTrace: at OrderService.ProcessPayment() in OrderService.cs:line 42] -> [System.TimeoutException: The operation timed out] ``` --- +## Sinks: writing to more than the console + +The console is the default destination. Extra destinations implement `ILogSink` (namespace `Tjidde.Logging.Sinks`) and receive every entry as an immutable `TjiddeLogEntry`: `Timestamp`, `Level`, `EventId`, `Category`, `ClassName`, `MethodName`, `Customer`, `Message`, `FormattedException`, `RenderedLine` (text or JSON, as on the console), `OutputFormat` and `IsMetrics`. All text in the entry is masked; it never contains unmasked values. + +```csharp +builder.Logging + .AddTjiddeLogger() + .AddTjiddeInMemorySink(capacity: 500) // built-in: inject InMemoryLogSink to read the entries + .AddTjiddeSink(); // your own sink, created by the container + +// or register directly: +builder.Services.AddSingleton(); +``` + +```csharp +public sealed class MyFileSink : ILogSink +{ + public void Write(TjiddeLogEntry entry) { /* fast, thread-safe */ } +} +``` + +- Sinks are called **synchronously** on the logging thread, in registration order. Keep `Write` fast and thread-safe; queue slow I/O yourself. +- An exception in a sink is ignored: logging never throws, and the console and the other sinks still get the entry. An entry logged from inside a sink is not sent to the sinks again. +- A sink must not take `ILogger` in its constructor (circular dependency). +- `InMemoryLogSink` keeps the newest `Capacity` entries (default 1000), with `GetSnapshot()`, `Count`, `Clear()` and the events `EntryAdded` and `Cleared`. Useful for UIs and tests. +- Set `WriteToConsole = false` (or `"TjiddeLogger": { "WriteToConsole": false }`) to write only to the sinks, for example in a desktop or terminal UI. It applies immediately when the options reload. + +--- + ## Output Format ``` @@ -210,6 +235,7 @@ YYYY-MM-DD: HH:mm:ss: [LEVEL] Class=>ClassName Method=>MethodName: Client=>Custo | Option | Type | Default | Description | |--------|------|---------|-------------| +| `WriteToConsole` | `bool` | `true` | Write entries to the console; `false` writes only to the registered sinks | | `IncludeScopes` | `bool` | `true` | Include scope information in output | | `UseUtcTimestamp` | `bool` | `false` | Write timestamps in UTC instead of local time | | `ResolveMethodNameFromStackTrace` | `bool` | `false` | Fall back to the stack trace for the method name when no `MethodName` scope is active (slow) | @@ -260,8 +286,7 @@ Values that are only known at runtime (a token from a vault, a customer code) ca The following capabilities are **intentionally not implemented** in v1.0 but the package is designed to support them: - **Method argument logging** — The `ICustomerContextAccessor` and scope design allow future decorator/interceptor-based enrichment. Attribute-based exclusion (`[SensitiveArgument]`) can be layered on top. -- **Sink abstraction** — Currently writes to Console. A future `ITjiddeLogSink` abstraction can route output to files, databases, or external systems. -- **Structured output formats** — JSON or OTLP output can be added as alternative formatters. +- **Additional structured outputs** — JSON is built in; OTLP/log-record output can be added as an alternative formatter or sink. - **Automatic argument logging** — Explicitly deferred due to privacy, security, and performance risks. When added, it will require opt-in per method or argument. --- @@ -280,8 +305,13 @@ Tjidde.Logging/ │ ├── IExceptionFormatter.cs # Exception formatting contract │ └── ExceptionFormatter.cs # Structured exception output ├── Logging/ +│ ├── ConsoleLogProcessor.cs # Background console writer (default sink) │ ├── TjiddeLogger.cs # ILogger implementation │ └── TjiddeLoggerProvider.cs # ILoggerProvider implementation +├── Sinks/ +│ ├── ILogSink.cs # Extra destinations for entries +│ ├── TjiddeLogEntry.cs # Immutable, masked entry passed to sinks +│ └── InMemoryLogSink.cs # Built-in bounded in-memory sink ├── Masking/ │ ├── IMaskedKeysAccessor.cs # Runtime keys abstraction (+ GlobalMaskedKeysAccessor) │ ├── MaskedKeysStore.cs # Per-host runtime keys (UseIsolatedMaskedKeys) diff --git a/TjiddeLogger.sln b/TjiddeLogger.sln index 079c8f6..bc0daf2 100644 --- a/TjiddeLogger.sln +++ b/TjiddeLogger.sln @@ -16,6 +16,10 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Tjidde.Logging.DesktopApp", EndProject Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Tjidde.Logging.TuiApp", "samples\Tjidde.Logging.TuiApp\Tjidde.Logging.TuiApp.csproj", "{CA63A14A-CC92-4DD3-A55D-3644AA99D31D}" EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "benchmarks", "benchmarks", "{66320409-64EC-F7C5-3DEF-65E7510DAAD1}" +EndProject +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Tjidde.Logging.Benchmarks", "benchmarks\Tjidde.Logging.Benchmarks\Tjidde.Logging.Benchmarks.csproj", "{2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -86,6 +90,18 @@ Global {CA63A14A-CC92-4DD3-A55D-3644AA99D31D}.Release|x64.Build.0 = Release|Any CPU {CA63A14A-CC92-4DD3-A55D-3644AA99D31D}.Release|x86.ActiveCfg = Release|Any CPU {CA63A14A-CC92-4DD3-A55D-3644AA99D31D}.Release|x86.Build.0 = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|Any CPU.Build.0 = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|x64.ActiveCfg = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|x64.Build.0 = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|x86.ActiveCfg = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Debug|x86.Build.0 = Debug|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|Any CPU.ActiveCfg = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|Any CPU.Build.0 = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|x64.ActiveCfg = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|x64.Build.0 = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|x86.ActiveCfg = Release|Any CPU + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E}.Release|x86.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE @@ -94,5 +110,6 @@ Global {C8E0BBB7-9CA6-4551-B342-B7620289575E} = {5D20AA90-6969-D8BD-9DCD-8634F4692FDA} {E97826C8-FAF8-4145-9FF5-E9FD5929390B} = {5D20AA90-6969-D8BD-9DCD-8634F4692FDA} {CA63A14A-CC92-4DD3-A55D-3644AA99D31D} = {5D20AA90-6969-D8BD-9DCD-8634F4692FDA} + {2807FF2D-F8C0-4B7F-B8ED-DD7455DE394E} = {66320409-64EC-F7C5-3DEF-65E7510DAAD1} EndGlobalSection EndGlobal diff --git a/benchmarks/README.md b/benchmarks/README.md new file mode 100644 index 0000000..586c393 --- /dev/null +++ b/benchmarks/README.md @@ -0,0 +1,85 @@ +# Tjidde.Logging benchmarks + +[BenchmarkDotNet](https://benchmarkdotnet.org/) benchmarks for the logging path of `TjiddeLogger`: one call from +`ILogger.Log` to the rendered line. They measure the logger, not the console: every logger runs with +`WriteToConsole = false`, so nothing is queued for the console writer. Sensitive data masking is on (the default) +and the customer context is a fixed value, so every line has a customer part. + +| Benchmark | What it logs | +|------------------------|-----------------------------------------------------------------------------------------------| +| `Simple` | A constant message without properties (`LoggerMessage.Define`). | +| `Structured` | A template with three non-sensitive properties (`{UserId}`, `{ItemCount}`, `{Destination}`). | +| `SensitiveProperty` | A template with a sensitive property (`{Password}`): masked, message rebuilt from the template. | +| `StructuredWithScopes` | `Structured` with two active scopes: a text scope and a `MethodName` scope with two properties. | +| `StructuredWithSink` | `Structured` with one no-op `ILogSink`, so the `TjiddeLogEntry` is built as well. | +| `Disabled` | A `Debug` entry on a logger with minimum level `Information`: the `IsEnabled == false` path. | + +Every benchmark runs for both output formats (`Format = Text` and `Format = Json`). The other benchmarks have +no sinks and a framework `LoggerExternalScopeProvider` without active scopes, as in a normal host. + +## Running + +``` +dotnet run -c Release --project benchmarks/Tjidde.Logging.Benchmarks -- --filter '*' +``` + +Useful options: + +- `--filter '*Structured*'`: only the matching benchmarks. +- `--job short`: fewer iterations, for a quick check (less accurate). +- `--artifacts `: where the reports go (default `BenchmarkDotNet.Artifacts`, ignored by git). + +The benchmark project targets `net10.0` and needs the .NET 10 SDK. + +## Baseline + +Commit `325a711`, before any optimization. Default job, .NET 10.0.12, Intel Core i7-8565U (laptop, 4 cores), +Windows 11. The microsecond results on this machine are noisy (BenchmarkDotNet reports multimodal distributions), +so compare the means as rough figures; the allocations are exact. + +| Method | Format | Mean | Allocated | +|----------------------|--------|----------:|----------:| +| Simple | Text | 4,066 ns | 1224 B | +| Structured | Text | 10,722 ns | 1568 B | +| SensitiveProperty | Text | 15,507 ns | 2376 B | +| StructuredWithScopes | Text | 23,864 ns | 2736 B | +| StructuredWithSink | Text | 15,735 ns | 1680 B | +| Disabled | Text | 7.8 ns | - | +| Simple | Json | 12,218 ns | 2145 B | +| Structured | Json | 26,271 ns | 3914 B | +| SensitiveProperty | Json | 26,299 ns | 4042 B | +| StructuredWithScopes | Json | 39,634 ns | 4436 B | +| StructuredWithSink | Json | 21,645 ns | 4026 B | +| Disabled | Json | 10.5 ns | - | + +Most of the time goes to sensitive data masking: `SensitiveDataMasker.MaskMessage` runs two regular expressions +per sensitive key (17 built-in keys, so 34 regex scans) over the message and over every string property and scope +value, even when the text contains none of the keys. + +## After optimization + +Commit under test: `improvements` after the masking pre-check, allocation reductions and `Utf8JsonWriter` JSON +changes. Measured with `--job short` on .NET 10.0.12, Intel Core i7-8565U (laptop, 4 cores), Windows 11. ShortRun +uses only three measured iterations, so use the means as a quick regression signal; allocations are the more stable +part of this run. + +| Method | Format | Mean | Allocated | Mean vs baseline | Alloc vs baseline | +|----------------------|--------|-----------:|----------:|-----------------:|------------------:| +| Simple | Text | 499.2 ns | 296 B | -87.7% | -75.8% | +| Structured | Text | 813.3 ns | 568 B | -92.4% | -63.8% | +| SensitiveProperty | Text | 1,194.2 ns | 1128 B | -92.3% | -52.5% | +| StructuredWithScopes | Text | 1,272.0 ns | 1016 B | -94.7% | -62.9% | +| StructuredWithSink | Text | 895.0 ns | 680 B | -94.3% | -59.5% | +| Disabled | Text | 3.3 ns | - | -57.6% | n/a | +| Simple | Json | 1,124.7 ns | 936 B | -90.8% | -56.4% | +| Structured | Json | 1,638.8 ns | 1400 B | -93.8% | -64.2% | +| SensitiveProperty | Json | 1,951.7 ns | 1912 B | -92.6% | -52.7% | +| StructuredWithScopes | Json | 2,072.0 ns | 1808 B | -94.8% | -59.2% | +| StructuredWithSink | Json | 1,769.5 ns | 1512 B | -91.8% | -62.4% | +| Disabled | Json | 3.0 ns | - | -71.0% | n/a | + +The masking pre-check removes almost all regex work for entries whose text and values do not contain a configured +key, which explains the large wins in the simple and structured text paths. The allocation work removes per-entry +temporary lists, scope closures and intermediate text strings, cutting text allocations by roughly 53-76%. The JSON +writer change avoids building two dictionaries and writes common primitive values directly, which brings JSON +allocations down by roughly 53-64% while preserving the rendered output. diff --git a/benchmarks/Tjidde.Logging.Benchmarks/BenchmarkInfrastructure.cs b/benchmarks/Tjidde.Logging.Benchmarks/BenchmarkInfrastructure.cs new file mode 100644 index 0000000..6977a64 --- /dev/null +++ b/benchmarks/Tjidde.Logging.Benchmarks/BenchmarkInfrastructure.cs @@ -0,0 +1,67 @@ +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Tjidde.Logging.Context; +using Tjidde.Logging.Sinks; + +namespace Tjidde.Logging.Benchmarks; + +/// An options monitor with fixed options and no change notifications. +internal sealed class StaticOptionsMonitor : IOptionsMonitor +{ + public StaticOptionsMonitor(T value) => CurrentValue = value; + + public T CurrentValue { get; } + + public T Get(string? name) => CurrentValue; + + public IDisposable? OnChange(Action listener) => null; +} + +/// A fixed customer, so every entry carries a customer part. +internal sealed class FixedCustomerContextAccessor : ICustomerContextAccessor +{ + private readonly string? _customer; + + public FixedCustomerContextAccessor(string? customer) => _customer = customer; + + public string? GetCustomerContext() => _customer; +} + +/// +/// A scope provider that always reports the same scopes: a text scope and a structured scope with a +/// MethodName, as BeginMethodScope creates. Deterministic, unlike an AsyncLocal-based provider +/// whose scopes would have to be pushed inside the measured call. +/// +internal sealed class FixedScopeProvider : IExternalScopeProvider +{ + private readonly object[] _scopes = + [ + "Order pipeline", + new KeyValuePair[] + { + new("MethodName", "ProcessOrder"), + new("OrderId", 12345), + new("Region", "eu-west") + } + ]; + + public void ForEachScope(Action callback, TState state) + { + foreach (var scope in _scopes) + callback(scope, state); + } + + public IDisposable Push(object? state) => NullDisposable.Instance; + + private sealed class NullDisposable : IDisposable + { + public static readonly NullDisposable Instance = new(); + public void Dispose() { } + } +} + +/// A sink that discards every entry, to measure building the entry without any I/O. +internal sealed class NoOpSink : ILogSink +{ + public void Write(TjiddeLogEntry entry) { } +} diff --git a/benchmarks/Tjidde.Logging.Benchmarks/LoggerBenchmarks.cs b/benchmarks/Tjidde.Logging.Benchmarks/LoggerBenchmarks.cs new file mode 100644 index 0000000..0bc42d8 --- /dev/null +++ b/benchmarks/Tjidde.Logging.Benchmarks/LoggerBenchmarks.cs @@ -0,0 +1,108 @@ +using BenchmarkDotNet.Attributes; +using Microsoft.Extensions.Logging; +using Tjidde.Logging.Logging; +using Tjidde.Logging.Masking; +using Tjidde.Logging.Options; +using Tjidde.Logging.Sinks; + +namespace Tjidde.Logging.Benchmarks; + +/// +/// Measures one log call through , from ILogger.Log to the rendered line. +/// The console is off ( = false) so console I/O is not measured; +/// sensitive data masking is on (the default). Every scenario runs for both output formats. +/// +[MemoryDiagnoser] +public class LoggerBenchmarks +{ + private static readonly Action SimpleMessage = + LoggerMessage.Define(LogLevel.Information, new EventId(1, "Simple"), "Order processed successfully"); + + private static readonly Action StructuredMessage = + LoggerMessage.Define(LogLevel.Information, new EventId(2, "Structured"), + "User {UserId} ordered {ItemCount} items for {Destination}"); + + private static readonly Action SensitiveMessage = + LoggerMessage.Define(LogLevel.Information, new EventId(3, "Sensitive"), + "Login for {UserName} with {Password}"); + + private static readonly Action DebugMessage = + LoggerMessage.Define(LogLevel.Debug, new EventId(4, "Debug"), "Cache lookup for {Key}"); + + private readonly List _providers = []; + + private ILogger _logger = null!; + private ILogger _scopedLogger = null!; + private ILogger _sinkLogger = null!; + private ILogger _infoLevelLogger = null!; + + [Params(TjiddeLogOutputFormat.Text, TjiddeLogOutputFormat.Json)] + public TjiddeLogOutputFormat Format { get; set; } + + [GlobalSetup] + public void Setup() + { + // Logger without scopes: IncludeScopes is on (the default), but no scope is active. + _logger = CreateLogger(new TjiddeLoggerOptions()); + + // Logger with a text scope and a structured MethodName scope active. + _scopedLogger = CreateLogger(new TjiddeLoggerOptions(), scopeProvider: new FixedScopeProvider()); + + // Logger with one sink that discards the entries, so the TjiddeLogEntry is built. + _sinkLogger = CreateLogger(new TjiddeLoggerOptions(), sinks: [new NoOpSink()]); + + // Logger with minimum level Information, for the IsEnabled == false path. +#pragma warning disable CS0618 // MinimumLevel is obsolete but still honored; it is the cheapest way to filter here + _infoLevelLogger = CreateLogger(new TjiddeLoggerOptions { MinimumLevel = LogLevel.Information }); +#pragma warning restore CS0618 + } + + [GlobalCleanup] + public void Cleanup() + { + foreach (var provider in _providers) + provider.Dispose(); + } + + private ILogger CreateLogger(TjiddeLoggerOptions options, IExternalScopeProvider? scopeProvider = null, ILogSink[]? sinks = null) + { + options.OutputFormat = Format; + options.WriteToConsole = false; + + var provider = new TjiddeLoggerProvider( + new StaticOptionsMonitor(options), + new FixedCustomerContextAccessor("ACME"), + new MaskedKeysStore(), + TimeProvider.System, + sinks); + + // Without fixed scopes: the framework's own scope provider with no scope pushed, as in a host. + provider.SetScopeProvider(scopeProvider ?? new LoggerExternalScopeProvider()); + _providers.Add(provider); + return provider.CreateLogger("Tjidde.Logging.Benchmarks.OrderService"); + } + + /// A constant message without properties. + [Benchmark(Baseline = true)] + public void Simple() => SimpleMessage(_logger, null); + + /// A message template with three non-sensitive properties. + [Benchmark] + public void Structured() => StructuredMessage(_logger, 42, 3, "Amsterdam", null); + + /// A message template with a sensitive property: masked and the message rebuilt from the template. + [Benchmark] + public void SensitiveProperty() => SensitiveMessage(_logger, "alice", "hunter2!", null); + + /// The structured message with two active scopes (text and MethodName/properties). + [Benchmark] + public void StructuredWithScopes() => StructuredMessage(_scopedLogger, 42, 3, "Amsterdam", null); + + /// The structured message with one (no-op) sink registered, so the sink entry is built too. + [Benchmark] + public void StructuredWithSink() => StructuredMessage(_sinkLogger, 42, 3, "Amsterdam", null); + + /// A debug entry on a logger whose minimum level is Information: IsEnabled is false. + [Benchmark] + public void Disabled() => DebugMessage(_infoLevelLogger, 7, null); +} diff --git a/benchmarks/Tjidde.Logging.Benchmarks/Program.cs b/benchmarks/Tjidde.Logging.Benchmarks/Program.cs new file mode 100644 index 0000000..ed0cf89 --- /dev/null +++ b/benchmarks/Tjidde.Logging.Benchmarks/Program.cs @@ -0,0 +1,8 @@ +using BenchmarkDotNet.Running; + +namespace Tjidde.Logging.Benchmarks; + +public static class Program +{ + public static void Main(string[] args) => BenchmarkSwitcher.FromAssembly(typeof(Program).Assembly).Run(args); +} diff --git a/benchmarks/Tjidde.Logging.Benchmarks/Tjidde.Logging.Benchmarks.csproj b/benchmarks/Tjidde.Logging.Benchmarks/Tjidde.Logging.Benchmarks.csproj new file mode 100644 index 0000000..980484d --- /dev/null +++ b/benchmarks/Tjidde.Logging.Benchmarks/Tjidde.Logging.Benchmarks.csproj @@ -0,0 +1,22 @@ + + + + Exe + net10.0 + enable + latest + enable + false + true + + + + + + + + + + + + diff --git a/docs/AI-INTEGRATION.md b/docs/AI-INTEGRATION.md index 5b615a5..9832c77 100644 --- a/docs/AI-INTEGRATION.md +++ b/docs/AI-INTEGRATION.md @@ -13,15 +13,17 @@ Tjidde.Logging is a logging provider for `Microsoft.Extensions.Logging`. Applica - masking of sensitive values (passwords, tokens, API keys, and so on) - compact single-line exception formatting - optional OpenTelemetry span events +- optional extra destinations (sinks) next to, or instead of, the console Target frameworks: `net7.0`, `net8.0`, `net9.0`, `net10.0`. | Namespace | Contains | |---|---| -| `Tjidde.Logging.Extensions` | `AddTjiddeLogger`, `UseTjiddeJsonFormat`, `UseTjiddeTextFormat`, `UseIsolatedMaskedKeys`, `BeginMethodScope`, `LogMetrics` | +| `Tjidde.Logging.Extensions` | `AddTjiddeLogger`, `UseTjiddeJsonFormat`, `UseTjiddeTextFormat`, `UseIsolatedMaskedKeys`, `AddTjiddeSink`, `AddTjiddeInMemorySink`, `BeginMethodScope`, `LogMetrics` | | `Tjidde.Logging.Options` | `TjiddeLoggerOptions`, `TjiddeLogOutputFormat` | | `Tjidde.Logging.Context` | `ICustomerContextAccessor`, `AsyncLocalCustomerContextAccessor`, `CustomerContext` | | `Tjidde.Logging.Masking` | `IMaskedKeysAccessor`, `MaskedKeysStore`, `MaskedKeysContext` | +| `Tjidde.Logging.Sinks` | `ILogSink`, `TjiddeLogEntry`, `InMemoryLogSink` | Prefer the DI route for testable code: implement `ICustomerContextAccessor` and use `UseIsolatedMaskedKeys()` with an injected `MaskedKeysStore`. The static `CustomerContext` and `MaskedKeysContext` are the convenience defaults; `MaskedKeysContext` is shared by every host and test in the process. @@ -287,6 +289,23 @@ builder.Services.AddOpenTelemetry() .WithTracing(tracing => tracing.AddSource("Tjidde.Logging")); ``` +## Sinks (other destinations) + +The console is the default destination. To also send entries elsewhere, register an `ILogSink`: + +```csharp +builder.Logging + .AddTjiddeLogger() + .AddTjiddeInMemorySink(capacity: 500) // built-in; inject InMemoryLogSink to read it + .AddTjiddeSink(); // or: builder.Services.AddSingleton() +``` + +- `ILogSink.Write(TjiddeLogEntry entry)` receives an immutable entry with `Timestamp`, `Level`, `EventId`, `Category`, `ClassName`, `MethodName`, `Customer`, `Message`, `FormattedException`, `RenderedLine`, `OutputFormat` and `IsMetrics`. All text is already masked. +- Sinks run synchronously on the logging thread: keep `Write` fast and thread-safe, and queue slow I/O yourself. A sink that throws is ignored; logging and the other sinks continue. +- Do not inject `ILogger` or `ILoggerFactory` into a sink's constructor (circular dependency). +- Recognize metrics entries with `entry.IsMetrics` (event `MetricsEventId`), not with the obsolete `MetricsLoggerExtensions.Metrics` level. +- Set `WriteToConsole = false` to write only to the sinks (for example in a desktop or terminal UI). + ## Shutdown and flushing A background thread writes the lines to the console, so log calls do not wait for console I/O. Pending lines are flushed when the host stops, when a `LoggerFactory` is disposed, and on normal process exit. Lines still queued when the process crashes can be lost. @@ -295,7 +314,7 @@ A background thread writes the lines to the console, so log calls do not wait fo The clock is the `TimeProvider` registered in DI, or `TimeProvider.System` when none is registered. To assert on timestamps, register a `FakeTimeProvider` (package `Microsoft.Extensions.TimeProvider.Testing`) with `services.AddSingleton(clock)`. -In unit tests, inject `NullLogger.Instance` (from `Microsoft.Extensions.Logging.Abstractions`) instead of the Tjidde logger. If a test must read the console output, dispose the `LoggerFactory` first so all lines have been written. +In unit tests, inject `NullLogger.Instance` (from `Microsoft.Extensions.Logging.Abstractions`) instead of the Tjidde logger. To assert on what the Tjidde logger writes, use `AddTjiddeInMemorySink()` (optionally with `WriteToConsole = false`) and read the injected `InMemoryLogSink.GetSnapshot()`: sinks are called synchronously, so no flushing is needed. If a test must read the console output instead, dispose the `LoggerFactory` first so all lines have been written. ## Options reference @@ -304,6 +323,7 @@ Section name in `appsettings.json`: `TjiddeLogger`. | Option | Type | Default | Meaning | |---|---|---|---| | `OutputFormat` | `TjiddeLogOutputFormat` | `Text` | `Text` or `Json`. | +| `WriteToConsole` | `bool` | `true` | Write entries to the console. `false` writes only to the registered sinks. | | `MinimumLevel` | `LogLevel` | `Trace` | Obsolete, removed in 2.0: use `Logging:Tjidde:LogLevel`. Minimum level when no category rule matches. | | `CategoryMinimumLevels` | `IDictionary` | empty | Obsolete, removed in 2.0: use `Logging:Tjidde:LogLevel`. Minimum level per category or namespace prefix; the key `Default` is the fallback. | | `IncludeScopes` | `bool` | `true` | Append scope values to each entry. Also required for `BeginMethodScope`. | diff --git a/docs/wiki-en.md b/docs/wiki-en.md index 0601f95..455b9e4 100644 --- a/docs/wiki-en.md +++ b/docs/wiki-en.md @@ -12,8 +12,9 @@ 8. [Exception Formatting](#exception-formatting) 9. [Scopes](#scopes) 10. [Metrics Entries](#metrics-entries) -11. [CI/CD (GitHub Actions)](#cicd-github-actions) -12. [Future Work](#future-work) +11. [Sinks](#sinks) +12. [CI/CD (GitHub Actions)](#cicd-github-actions) +13. [Future Work](#future-work) --- @@ -42,7 +43,7 @@ dotnet add package Tjidde.Logging Or add it manually to your `.csproj`: ```xml - + ``` --- @@ -110,15 +111,15 @@ public class OrderService Every log entry is written as a **single line** in the following format: ``` -YYYY-MM-DD: HH:mm:ss: [LEVEL] CS=>ClassName Method=>MethodName: Client=>Customer: Message [Masked: key1, key2] | Exception: [...] | Scopes: scope1 > scope2 +YYYY-MM-DD: HH:mm:ss: [LEVEL] Class=>ClassName Method=>MethodName: Client=>Customer: Message [Masked: key1, key2] | Exception: [...] | Scopes: scope1 > scope2 ``` ### Example output ``` -2026-03-18: 09:15:41: [INFORMATION] CS=>OrderService Method=>PlaceOrder: Client=>AcmeCorp: Order 42 placed successfully -2026-03-18: 09:15:42: [ERROR] CS=>PaymentService Method=>ProcessPayment: Client=>AcmeCorp: Payment failed | Exception: [System.InvalidOperationException: Gateway timeout] -2026-03-18: 09:15:43: [WARNING] CS=>AuthService Method=>Login: Login with password [REDACTED] +2026-03-18: 09:15:41: [INFORMATION] Class=>OrderService Method=>PlaceOrder: Client=>AcmeCorp: Order 42 placed successfully +2026-03-18: 09:15:42: [ERROR] Class=>PaymentService Method=>ProcessPayment: Client=>AcmeCorp: Payment failed | Exception: [System.InvalidOperationException: Gateway timeout] +2026-03-18: 09:15:43: [WARNING] Class=>AuthService Method=>Login: Login with password [REDACTED] ``` ### Log levels @@ -278,6 +279,7 @@ builder.Logging.AddTjiddeLogger(options => | Option | Type | Default | Description | |---|---|---|---| | `OutputFormat` | `TjiddeLogOutputFormat` | `Text` | Log rendering mode: `Text` or `Json` (Elasticsearch-friendly JSON line). | +| `WriteToConsole` | `bool` | `true` | Writes entries to the console. `false` writes only to the registered [sinks](#sinks). | | `MinimumLevel` *(obsolete)* | `LogLevel` | `Trace` | Global minimum log level fallback when no category override matches. Use `Logging:Tjidde:LogLevel` instead; removed in 2.0. | | `CategoryMinimumLevels` *(obsolete)* | `IDictionary` | `{}` | Category/namespace/class-specific minimum levels. Use `Logging:Tjidde:LogLevel` instead; removed in 2.0. | | `EnableOpenTelemetryExport` | `bool` | `false` | Emits each log as an OpenTelemetry event on the current `Activity` (for OTEL pipelines). | @@ -375,7 +377,7 @@ CustomerContext.Set("AcmeCorp"); // All log entries from this point forward will include "AcmeCorp:" in the output. _logger.LogInformation("Processing started"); -// → 2026-03-18: 09:00:00: [INFORMATION] MyService: AcmeCorp: Processing started +// → 2026-03-18: 09:00:00: [INFORMATION] Class=>MyService: Client=>AcmeCorp: Processing started ``` ### Clearing the context @@ -568,7 +570,7 @@ _logger.LogMetrics(new EventId(200), "throughput_rps={Rps}", rps); ### Example output ``` -2026-03-18: 11:00:00: [METRICS] OrderService ProcessOrder: AcmeCorp: requests_total=42 +2026-03-18: 11:00:00: [METRICS] Class=>OrderService Method=>ProcessOrder: Client=>AcmeCorp: requests_total=42 ``` The `[METRICS]` label is printed in **Magenta** in the console for easy visual distinction. @@ -583,6 +585,63 @@ Earlier versions logged metrics at the custom level `MetricsLoggerExtensions.Met --- +## Sinks + +The console is the default destination. To send entries somewhere else as well (a UI, a file, a test assertion), implement `ILogSink` (namespace `Tjidde.Logging.Sinks`) or use the built-in `InMemoryLogSink`. + +### Registering sinks + +```csharp +builder.Logging + .AddTjiddeLogger() + .AddTjiddeInMemorySink(capacity: 500) // built-in, inject InMemoryLogSink to read it + .AddTjiddeSink(); // created by the container, also injectable as MyFileSink + +builder.Logging.AddTjiddeSink(new MySink()); // an existing instance +builder.Services.AddSingleton(); // plain DI works too +``` + +### Writing a sink + +```csharp +public sealed class MyFileSink : ILogSink +{ + public void Write(TjiddeLogEntry entry) + { + // entry.RenderedLine is exactly what the console gets (text or JSON, see entry.OutputFormat) + } +} +``` + +`TjiddeLogEntry` is immutable and contains only masked data: + +| Property | Description | +|---|---| +| `Timestamp` | `DateTimeOffset`; UTC or local, following `UseUtcTimestamp` | +| `Level` / `EventId` | Level and event ID; `IsMetrics` is `true` for `LogMetrics` entries (event `Metrics`) | +| `Category` / `ClassName` / `MethodName` | Logger category, its last segment, and the method from a `MethodName` scope | +| `Customer` | The customer context, or `null` | +| `Message` | The rendered, masked message | +| `FormattedException` | The formatted, masked exception, or `null` | +| `RenderedLine` / `OutputFormat` | The complete rendered line and its format | + +Rules: + +- Sinks are called **synchronously** on the thread that logs, in registration order. `Write` must be fast and thread-safe; queue slow I/O yourself. +- An exception thrown by a sink is ignored: the log call never throws, and the console and the other sinks still receive the entry. +- An entry logged from inside `Write` is not sent to the sinks again, so a sink cannot recurse. +- A sink must not take `ILogger` or `ILoggerFactory` in its constructor (circular dependency). + +### InMemoryLogSink + +Keeps the newest `Capacity` entries (default 1000) and drops the oldest. `GetSnapshot()` returns a copy, oldest first; `Count`, `Clear()`, and the events `EntryAdded` (on the logging thread) and `Cleared` complete it. All members are thread-safe. The samples in `samples/` use it to show the log in a Blazor, Avalonia and terminal UI. + +### Console off + +`WriteToConsole = false` writes only to the sinks, for example in a desktop or terminal UI where console output is not wanted. It can be set in `appsettings.json` (`"TjiddeLogger": { "WriteToConsole": false }`) and applies immediately when the options reload. + +--- + ## CI/CD (GitHub Actions) Two workflows live in `.github/workflows/`: @@ -618,13 +677,25 @@ git push origin v1.0.4 The tag sets the package version: `v1.0.4` publishes `1.0.4`, and pre-releases such as `v1.1.0-beta.1` work too. The `` in the `.csproj` only applies to local builds. Publishing a version that already exists on nuget.org is skipped instead of failing. +### Public API and package validation + +Two checks guard against accidental breaking changes: + +- **Public API files.** `Microsoft.CodeAnalysis.PublicApiAnalyzers` compares the public API with two files next to `Tjidde.Logging.csproj`: `PublicAPI.Shipped.txt` (the API of the last release) and `PublicAPI.Unshipped.txt` (everything added since). New public API that is in neither file gives warning RS0016; add it to `PublicAPI.Unshipped.txt` (the RS0016 code fix in the IDE, or `dotnet format analyzers src/Tjidde.Logging/Tjidde.Logging.csproj --diagnostics RS0016`). A listed API that no longer matches, for example after a changed signature or default value, gives RS0017. +- **Package validation.** `dotnet pack` downloads the version in `` from nuget.org and fails if the new package breaks compatibility with it. + +After every release: + +1. Move all lines from `PublicAPI.Unshipped.txt` to `PublicAPI.Shipped.txt`. Both files keep `#nullable enable` as their first line, so `PublicAPI.Unshipped.txt` ends up with only that line. +2. Raise `` in `src/Tjidde.Logging/Tjidde.Logging.csproj` to the version you just released. + --- ## Future Work The following improvements and features are planned or considered for future releases: -- **File sink** — Write log output to rolling log files in addition to the console. +- **File sink** — A built-in `ILogSink` that writes rolling log files. - **Redaction audit log** — Optionally emit a separate audit entry listing which fields were redacted, for compliance scenarios. - **Custom sensitive key providers** — Allow injecting `ISensitiveKeyProvider` implementations so keys can be loaded from configuration or a secrets store at runtime. - **NuGet package signing** — Sign the NuGet package in the pipeline for supply-chain security. diff --git a/docs/wiki-nl.md b/docs/wiki-nl.md index ba2f020..b862961 100644 --- a/docs/wiki-nl.md +++ b/docs/wiki-nl.md @@ -12,8 +12,9 @@ 8. [Uitzonderingsopmaak](#uitzonderingsopmaak) 9. [Scopes](#scopes) 10. [Metrics-regels](#metrics-regels) -11. [CI/CD (GitHub Actions)](#cicd-github-actions) -12. [Toekomstige ontwikkelingen](#toekomstige-ontwikkelingen) +11. [Sinks](#sinks) +12. [CI/CD (GitHub Actions)](#cicd-github-actions) +13. [Toekomstige ontwikkelingen](#toekomstige-ontwikkelingen) --- @@ -42,7 +43,7 @@ dotnet add package Tjidde.Logging Of voeg het handmatig toe aan uw `.csproj`: ```xml - + ``` --- @@ -110,15 +111,15 @@ public class OrderService Elke logmelding wordt als **één regel** geschreven in het volgende formaat: ``` -YYYY-MM-DD: HH:mm:ss: [NIVEAU] CS=>KlasseNaam Method=>MethodeNaam: Client=>Klant: Bericht [Masked: sleutel1, sleutel2] | Exception: [...] | Scopes: scope1 > scope2 +YYYY-MM-DD: HH:mm:ss: [NIVEAU] Class=>KlasseNaam Method=>MethodeNaam: Client=>Klant: Bericht [Masked: sleutel1, sleutel2] | Exception: [...] | Scopes: scope1 > scope2 ``` ### Voorbeelduitvoer ``` -2026-03-18: 09:15:41: [INFORMATION] CS=>OrderService Method=>PlaceOrder: Client=>AcmeCorp: Bestelling 42 succesvol geplaatst -2026-03-18: 09:15:42: [ERROR] CS=>PaymentService Method=>ProcessPayment: Client=>AcmeCorp: Betaling mislukt | Exception: [System.InvalidOperationException: Gateway timeout] -2026-03-18: 09:15:43: [WARNING] CS=>AuthService Method=>Login: Inloggen met password [REDACTED] +2026-03-18: 09:15:41: [INFORMATION] Class=>OrderService Method=>PlaceOrder: Client=>AcmeCorp: Bestelling 42 succesvol geplaatst +2026-03-18: 09:15:42: [ERROR] Class=>PaymentService Method=>ProcessPayment: Client=>AcmeCorp: Betaling mislukt | Exception: [System.InvalidOperationException: Gateway timeout] +2026-03-18: 09:15:43: [WARNING] Class=>AuthService Method=>Login: Inloggen met password [REDACTED] ``` ### Logniveaus @@ -278,6 +279,7 @@ builder.Logging.AddTjiddeLogger(options => | Optie | Type | Standaard | Beschrijving | |---|---|---|---| | `OutputFormat` | `TjiddeLogOutputFormat` | `Text` | Weergavemodus: `Text` of `Json` (Elasticsearch-vriendelijke JSON-regel). | +| `WriteToConsole` | `bool` | `true` | Schrijft regels naar de console. `false` schrijft alleen naar de geregistreerde [sinks](#sinks). | | `MinimumLevel` *(verouderd)* | `LogLevel` | `Trace` | Globaal minimum logniveau als er geen categorie-override matcht. Gebruik `Logging:Tjidde:LogLevel`; verdwijnt in 2.0. | | `CategoryMinimumLevels` *(verouderd)* | `IDictionary` | `{}` | Categorie-/namespace-/klasse-specifieke minimum niveaus. Gebruik `Logging:Tjidde:LogLevel`; verdwijnt in 2.0. | | `EnableOpenTelemetryExport` | `bool` | `false` | Stuurt elke logregel als OpenTelemetry-event op de huidige `Activity` (voor OTEL-pipelines). | @@ -375,7 +377,7 @@ CustomerContext.Set("AcmeCorp"); // Alle logmeldingen vanaf dit punt bevatten "AcmeCorp:" in de uitvoer. _logger.LogInformation("Verwerking gestart"); -// → 2026-03-18: 09:00:00: [INFORMATION] MyService: AcmeCorp: Verwerking gestart +// → 2026-03-18: 09:00:00: [INFORMATION] Class=>MyService: Client=>AcmeCorp: Verwerking gestart ``` ### Context wissen @@ -568,7 +570,7 @@ _logger.LogMetrics(new EventId(200), "throughput_rps={Rps}", rps); ### Voorbeelduitvoer ``` -2026-03-18: 11:00:00: [METRICS] OrderService ProcessOrder: AcmeCorp: requests_total=42 +2026-03-18: 11:00:00: [METRICS] Class=>OrderService Method=>ProcessOrder: Client=>AcmeCorp: requests_total=42 ``` Het label `[METRICS]` wordt in **Magenta** weergegeven in de console voor eenvoudige visuele herkenning. @@ -583,6 +585,63 @@ Eerdere versies logden metrics op het aangepaste niveau `MetricsLoggerExtensions --- +## Sinks + +De console is de standaardbestemming. Om regels ook ergens anders heen te sturen (een UI, een bestand, een test), implementeer je `ILogSink` (namespace `Tjidde.Logging.Sinks`) of gebruik je de ingebouwde `InMemoryLogSink`. + +### Sinks registreren + +```csharp +builder.Logging + .AddTjiddeLogger() + .AddTjiddeInMemorySink(capacity: 500) // ingebouwd, injecteer InMemoryLogSink om te lezen + .AddTjiddeSink(); // gemaakt door de container, ook injecteerbaar als MyFileSink + +builder.Logging.AddTjiddeSink(new MySink()); // een bestaande instantie +builder.Services.AddSingleton(); // gewone DI werkt ook +``` + +### Een sink schrijven + +```csharp +public sealed class MyFileSink : ILogSink +{ + public void Write(TjiddeLogEntry entry) + { + // entry.RenderedLine is precies wat de console krijgt (tekst of JSON, zie entry.OutputFormat) + } +} +``` + +`TjiddeLogEntry` is immutable en bevat alleen gemaskeerde gegevens: + +| Eigenschap | Beschrijving | +|---|---| +| `Timestamp` | `DateTimeOffset`; UTC of lokaal, volgens `UseUtcTimestamp` | +| `Level` / `EventId` | Niveau en event-ID; `IsMetrics` is `true` voor `LogMetrics`-regels (event `Metrics`) | +| `Category` / `ClassName` / `MethodName` | Loggercategorie, het laatste deel daarvan, en de methode uit een `MethodName`-scope | +| `Customer` | De klantcontext, of `null` | +| `Message` | Het gerenderde, gemaskeerde bericht | +| `FormattedException` | De opgemaakte, gemaskeerde exception, of `null` | +| `RenderedLine` / `OutputFormat` | De volledige gerenderde regel en het formaat daarvan | + +Regels: + +- Sinks worden **synchroon** aangeroepen op de thread die logt, in volgorde van registratie. `Write` moet snel en thread-safe zijn; zet trage I/O zelf in een wachtrij. +- Een exception uit een sink wordt genegeerd: de logaanroep gooit nooit, en de console en de andere sinks krijgen de regel nog steeds. +- Een regel die binnen `Write` gelogd wordt, gaat niet opnieuw naar de sinks, dus een sink kan niet recursief worden. +- Een sink mag geen `ILogger` of `ILoggerFactory` in zijn constructor vragen (circulaire afhankelijkheid). + +### InMemoryLogSink + +Bewaart de nieuwste `Capacity` regels (standaard 1000) en laat de oudste vallen. `GetSnapshot()` geeft een kopie, oudste eerst; daarnaast zijn er `Count`, `Clear()` en de events `EntryAdded` (op de logthread) en `Cleared`. Alle members zijn thread-safe. De voorbeelden in `samples/` gebruiken hem om de log te tonen in een Blazor-, Avalonia- en terminal-UI. + +### Console uitzetten + +`WriteToConsole = false` schrijft alleen naar de sinks, bijvoorbeeld in een desktop- of terminal-UI waar console-uitvoer ongewenst is. Het kan in `appsettings.json` (`"TjiddeLogger": { "WriteToConsole": false }`) en geldt direct wanneer de opties herladen. + +--- + ## CI/CD (GitHub Actions) In `.github/workflows/` staan twee workflows: @@ -618,13 +677,25 @@ git push origin v1.0.4 De tag bepaalt de pakketversie: `v1.0.4` publiceert `1.0.4`, en pre-releases zoals `v1.1.0-beta.1` werken ook. De `` in de `.csproj` geldt alleen voor lokale builds. Een versie die al op nuget.org staat, wordt overgeslagen in plaats van dat de workflow faalt. +### Publieke API en package validation + +Twee controles voorkomen onbedoelde breaking changes: + +- **Publieke-API-bestanden.** `Microsoft.CodeAnalysis.PublicApiAnalyzers` vergelijkt de publieke API met twee bestanden naast `Tjidde.Logging.csproj`: `PublicAPI.Shipped.txt` (de API van de laatste release) en `PublicAPI.Unshipped.txt` (alles wat daarna is toegevoegd). Nieuwe publieke API die in geen van beide staat, geeft waarschuwing RS0016; voeg die toe aan `PublicAPI.Unshipped.txt` (met de RS0016-codefix in de IDE, of `dotnet format analyzers src/Tjidde.Logging/Tjidde.Logging.csproj --diagnostics RS0016`). Een vermelde API die niet meer klopt, bijvoorbeeld na een gewijzigde signatuur of standaardwaarde, geeft RS0017. +- **Package validation.** `dotnet pack` haalt de versie uit `` op van nuget.org en faalt als het nieuwe pakket daarmee niet compatibel is. + +Na elke release: + +1. Verplaats alle regels uit `PublicAPI.Unshipped.txt` naar `PublicAPI.Shipped.txt`. Beide bestanden houden `#nullable enable` als eerste regel, dus in `PublicAPI.Unshipped.txt` blijft alleen die regel over. +2. Hoog `` in `src/Tjidde.Logging/Tjidde.Logging.csproj` op naar de versie die je net hebt uitgebracht. + --- ## Toekomstige ontwikkelingen De volgende verbeteringen en functies zijn gepland of worden overwogen voor toekomstige releases: -- **Bestandssink** — Loguitvoer wegschrijven naar roterende logbestanden naast de console. +- **Bestandssink** — Een ingebouwde `ILogSink` die naar roterende logbestanden schrijft. - **Redactie-auditlog** — Optioneel een aparte auditmelding uitsturen met de lijst van gemaskeerde velden, voor compliancescenario's. - **Aangepaste gevoelige-sleutelproviders** — Het injecteren van `ISensitiveKeyProvider`-implementaties toestaan, zodat sleutels tijdens runtime uit configuratie of een secrets store kunnen worden geladen. - **NuGet-pakketondertekening** — Het NuGet-pakket ondertekenen in de pipeline voor supply-chain-beveiliging. diff --git a/samples/Tjidde.Logging.DemoApp/Components/Pages/Home.razor b/samples/Tjidde.Logging.DemoApp/Components/Pages/Home.razor index 2e95bbe..a33f157 100644 --- a/samples/Tjidde.Logging.DemoApp/Components/Pages/Home.razor +++ b/samples/Tjidde.Logging.DemoApp/Components/Pages/Home.razor @@ -1,7 +1,7 @@ @page "/" @rendermode RenderMode.InteractiveServer @using Tjidde.Logging.Context -@using Tjidde.Logging.DemoApp.Logging +@using Tjidde.Logging.Sinks @using Tjidde.Logging.Extensions @using Microsoft.Extensions.Logging @inject ILogger Logger @@ -23,7 +23,7 @@ @@ -74,18 +74,18 @@
@foreach (var entry in Enumerable.Reverse(_entries)) { -
+
- @LevelLabel(entry.Level) + @LevelLabel(entry) @entry.Timestamp.ToString("yyyy-MM-dd HH:mm:ss") @ShortCategory(entry.Category)
-
@entry.FormattedMessage
- @if (entry.ExceptionDetails is not null) +
@entry.Message
+ @if (entry.FormattedException is not null) {
Exception details - 
@entry.ExceptionDetails
+ 
@entry.FormattedException
}
@@ -97,15 +97,18 @@
@code { - private static readonly (string Label, LogLevel Level)[] _levels = + // "Metrics" is not a log level: it is logged with LogMetrics (Information + MetricsEventId). + private const int MetricsOption = -1; + + private static readonly (string Label, int Level)[] _levels = [ - ("Trace", LogLevel.Trace), - ("Debug", LogLevel.Debug), - ("Information", LogLevel.Information), - ("Warning", LogLevel.Warning), - ("Error", LogLevel.Error), - ("Critical", LogLevel.Critical), - ("Metrics", MetricsLoggerExtensions.Metrics) + ("Trace", (int)LogLevel.Trace), + ("Debug", (int)LogLevel.Debug), + ("Information", (int)LogLevel.Information), + ("Warning", (int)LogLevel.Warning), + ("Error", (int)LogLevel.Error), + ("Critical", (int)LogLevel.Critical), + ("Metrics", MetricsOption) ]; private string _customer = string.Empty; @@ -114,17 +117,22 @@ private bool _includeException; private bool _includeInner; private string _exceptionMessage = "Something went wrong"; - private IReadOnlyList _entries = []; + private IReadOnlyList _entries = []; protected override void OnInitialized() { - Sink.OnChanged += RefreshEntries; - _entries = Sink.GetEntries(); + Sink.EntryAdded += OnEntryAdded; + Sink.Cleared += OnCleared; + _entries = Sink.GetSnapshot(); } + private void OnEntryAdded(object? sender, TjiddeLogEntry entry) => RefreshEntries(); + + private void OnCleared(object? sender, EventArgs e) => RefreshEntries(); + private void RefreshEntries() { - _entries = Sink.GetEntries(); + _entries = Sink.GetSnapshot(); InvokeAsync(StateHasChanged); } @@ -145,7 +153,10 @@ inner); } - Logger.Log((LogLevel)_selectedLevel, ex, "{Message}", _message.Trim()); + if (_selectedLevel == MetricsOption) + Logger.LogMetrics(ex, "{Message}", _message.Trim()); + else + Logger.Log((LogLevel)_selectedLevel, ex, "{Message}", _message.Trim()); CustomerContext.Clear(); } @@ -158,13 +169,18 @@ return dot >= 0 ? category[(dot + 1)..] : category; } - private static string LevelCssClass(LogLevel level) => (int)level == 10 + // Metrics entries are recognized by their event ID (MetricsEventId), not by a log level. + private static string LevelCssClass(TjiddeLogEntry entry) => entry.IsMetrics ? "metrics" - : level.ToString().ToLower(); + : entry.Level.ToString().ToLower(); - private static string LevelLabel(LogLevel level) => (int)level == 10 + private static string LevelLabel(TjiddeLogEntry entry) => entry.IsMetrics ? "Metrics" - : level.ToString(); + : entry.Level.ToString(); - public void Dispose() => Sink.OnChanged -= RefreshEntries; + public void Dispose() + { + Sink.EntryAdded -= OnEntryAdded; + Sink.Cleared -= OnCleared; + } } diff --git a/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLogSink.cs b/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLogSink.cs deleted file mode 100644 index f6db61f..0000000 --- a/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLogSink.cs +++ /dev/null @@ -1,46 +0,0 @@ -using Microsoft.Extensions.Logging; - -namespace Tjidde.Logging.DemoApp.Logging; - -/// -/// A thread-safe in-memory sink that captures formatted log entries for display in the demo UI. -/// -public sealed class InMemoryLogSink -{ - private readonly List _entries = new(); - private readonly Lock _lock = new(); - - public event Action? OnChanged; - - public void Add(LogEntry entry) - { - lock (_lock) - { - _entries.Add(entry); - // Keep a reasonable cap so the UI stays responsive - if (_entries.Count > 200) - _entries.RemoveAt(0); - } - OnChanged?.Invoke(); - } - - public IReadOnlyList GetEntries() - { - lock (_lock) - return _entries.ToList(); - } - - public void Clear() - { - lock (_lock) - _entries.Clear(); - OnChanged?.Invoke(); - } -} - -public sealed record LogEntry( - DateTimeOffset Timestamp, - LogLevel Level, - string Category, - string FormattedMessage, - string? ExceptionDetails); diff --git a/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLoggerProvider.cs b/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLoggerProvider.cs deleted file mode 100644 index d60e9ee..0000000 --- a/samples/Tjidde.Logging.DemoApp/Logging/InMemoryLoggerProvider.cs +++ /dev/null @@ -1,78 +0,0 @@ -using Microsoft.Extensions.Logging; - -namespace Tjidde.Logging.DemoApp.Logging; - -/// -/// An that writes to so the demo UI -/// can display log entries alongside the Tjidde console output. -/// -[ProviderAlias("InMemory")] -public sealed class InMemoryLoggerProvider : ILoggerProvider -{ - private readonly InMemoryLogSink _sink; - - public InMemoryLoggerProvider(InMemoryLogSink sink) - { - _sink = sink; - } - - public ILogger CreateLogger(string categoryName) => - new InMemoryLogger(categoryName, _sink); - - public void Dispose() { } -} - -internal sealed class InMemoryLogger : ILogger -{ - private readonly string _category; - private readonly InMemoryLogSink _sink; - - public InMemoryLogger(string category, InMemoryLogSink sink) - { - _category = category; - _sink = sink; - } - - public IDisposable? BeginScope(TState state) where TState : notnull => null; - - public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; - - public void Log( - LogLevel logLevel, - EventId eventId, - TState state, - Exception? exception, - Func formatter) - { - if (!IsEnabled(logLevel)) return; - - var message = formatter(state, exception); - var exceptionDetails = exception is not null - ? FormatException(exception) - : null; - - _sink.Add(new LogEntry( - Timestamp: DateTimeOffset.Now, - Level: logLevel, - Category: _category, - FormattedMessage: message, - ExceptionDetails: exceptionDetails)); - } - - private static string FormatException(Exception ex) - { - var sb = new System.Text.StringBuilder(); - var current = ex; - var depth = 0; - while (current is not null) - { - if (depth > 0) sb.AppendLine(" ---> Inner exception:"); - sb.AppendLine($" {current.GetType().FullName}: {current.Message}"); - if (current.StackTrace is { } st) - sb.AppendLine(st); - current = current.InnerException; - depth++; - } - return sb.ToString().TrimEnd(); - } -} diff --git a/samples/Tjidde.Logging.DemoApp/Program.cs b/samples/Tjidde.Logging.DemoApp/Program.cs index 594de6d..90ee5c1 100644 --- a/samples/Tjidde.Logging.DemoApp/Program.cs +++ b/samples/Tjidde.Logging.DemoApp/Program.cs @@ -1,21 +1,16 @@ -using Tjidde.Logging.DemoApp.Logging; using Tjidde.Logging.Extensions; -using Microsoft.Extensions.DependencyInjection; var builder = WebApplication.CreateBuilder(args); -// Register the in-memory sink as a singleton so the UI can read from it -builder.Services.AddSingleton(); - -// Add Tjidde logger (writes formatted output to the console) -// Add our in-memory provider so the Blazor UI can also display entries +// Tjidde logger: writes formatted output to the console, and to the built-in in-memory sink +// (the last 200 entries) so the Blazor UI can display them. Inject InMemoryLogSink to read them. builder.Logging.ClearProviders(); -builder.Logging.AddTjiddeLogger(options => -{ - options.IncludeScopes = true; -}); -builder.Services.AddSingleton(sp => - new InMemoryLoggerProvider(sp.GetRequiredService())); +builder.Logging + .AddTjiddeLogger(options => + { + options.IncludeScopes = true; + }) + .AddTjiddeInMemorySink(capacity: 200); builder.Services.AddRazorComponents() .AddInteractiveServerComponents(); diff --git a/samples/Tjidde.Logging.DesktopApp/App.axaml b/samples/Tjidde.Logging.DesktopApp/App.axaml index 1376484..473daea 100644 --- a/samples/Tjidde.Logging.DesktopApp/App.axaml +++ b/samples/Tjidde.Logging.DesktopApp/App.axaml @@ -10,6 +10,7 @@ + diff --git a/samples/Tjidde.Logging.DesktopApp/Converters/LogLevelColorConverter.cs b/samples/Tjidde.Logging.DesktopApp/Converters/LogLevelColorConverter.cs index 5271aa3..6c9627f 100644 --- a/samples/Tjidde.Logging.DesktopApp/Converters/LogLevelColorConverter.cs +++ b/samples/Tjidde.Logging.DesktopApp/Converters/LogLevelColorConverter.cs @@ -1,15 +1,22 @@ using Avalonia.Data.Converters; using Avalonia.Media; -using Tjidde.Logging.Extensions; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Logging; using System.Globalization; namespace Tjidde.Logging.DesktopApp.Converters; +/// Badge color for a log entry; metrics entries are recognized by their event ID (). public sealed class LogLevelColorConverter : IValueConverter { public object Convert(object? value, Type targetType, object? parameter, CultureInfo culture) { + if (value is TjiddeLogEntry { IsMetrics: true }) + return new SolidColorBrush(Color.Parse("#e879f9")); + + if (value is TjiddeLogEntry entry) + value = entry.Level; + if (value is LogLevel level) { return level switch @@ -20,7 +27,6 @@ public object Convert(object? value, Type targetType, object? parameter, Culture LogLevel.Warning => new SolidColorBrush(Color.Parse("#FF9800")), LogLevel.Error => new SolidColorBrush(Color.Parse("#F44336")), LogLevel.Critical => new SolidColorBrush(Color.Parse("#9C27B0")), - _ when level == MetricsLoggerExtensions.Metrics => new SolidColorBrush(Color.Parse("#e879f9")), _ => new SolidColorBrush(Color.Parse("#555555")) }; } @@ -30,3 +36,17 @@ public object Convert(object? value, Type targetType, object? parameter, Culture public object ConvertBack(object? value, Type targetType, object? parameter, CultureInfo culture) => throw new NotSupportedException(); } + +/// Badge text for a log entry: the level, or "Metrics" for metrics entries. +public sealed class LogLevelLabelConverter : IValueConverter +{ + public object? Convert(object? value, Type targetType, object? parameter, CultureInfo culture) => value switch + { + TjiddeLogEntry { IsMetrics: true } => "Metrics", + TjiddeLogEntry entry => entry.Level.ToString(), + _ => value?.ToString() + }; + + public object ConvertBack(object? value, Type targetType, object? parameter, CultureInfo culture) + => throw new NotSupportedException(); +} diff --git a/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLogSink.cs b/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLogSink.cs deleted file mode 100644 index e273544..0000000 --- a/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLogSink.cs +++ /dev/null @@ -1,34 +0,0 @@ -using Microsoft.Extensions.Logging; -using System.Collections.Concurrent; - -namespace Tjidde.Logging.DesktopApp.Logging; - -public sealed class LogEntry -{ - public DateTimeOffset Timestamp { get; init; } - public LogLevel Level { get; init; } - public string Category { get; init; } = string.Empty; - public string FormattedMessage { get; init; } = string.Empty; - public string? ExceptionDetails { get; init; } -} - -public sealed class InMemoryLogSink -{ - private readonly ConcurrentQueue _entries = new(); - - public event Action? OnChanged; - - public void Add(LogEntry entry) - { - _entries.Enqueue(entry); - OnChanged?.Invoke(); - } - - public IReadOnlyList GetEntries() => _entries.ToArray(); - - public void Clear() - { - while (_entries.TryDequeue(out _)) { } - OnChanged?.Invoke(); - } -} diff --git a/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLoggerProvider.cs b/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLoggerProvider.cs deleted file mode 100644 index e219ac4..0000000 --- a/samples/Tjidde.Logging.DesktopApp/Logging/InMemoryLoggerProvider.cs +++ /dev/null @@ -1,50 +0,0 @@ -using Tjidde.Logging.Formatting; -using Microsoft.Extensions.Logging; - -namespace Tjidde.Logging.DesktopApp.Logging; - -[ProviderAlias("InMemory")] -public sealed class InMemoryLoggerProvider : ILoggerProvider -{ - private readonly InMemoryLogSink _sink; - - public InMemoryLoggerProvider(InMemoryLogSink sink) => _sink = sink; - - public ILogger CreateLogger(string categoryName) => new InMemoryLogger(categoryName, _sink); - - public void Dispose() { } -} - -internal sealed class InMemoryLogger : ILogger -{ - private readonly string _category; - private readonly InMemoryLogSink _sink; - - public InMemoryLogger(string category, InMemoryLogSink sink) - { - _category = category; - _sink = sink; - } - - public IDisposable? BeginScope(TState state) where TState : notnull => null; - - public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; - - public void Log(LogLevel logLevel, EventId eventId, TState state, - Exception? exception, Func formatter) - { - if (!IsEnabled(logLevel)) return; - - var message = formatter(state, exception); - var exDetails = exception is not null ? new ExceptionFormatter().Format(exception) : null; - - _sink.Add(new LogEntry - { - Timestamp = DateTimeOffset.Now, - Level = logLevel, - Category = _category, - FormattedMessage = message, - ExceptionDetails = exDetails - }); - } -} diff --git a/samples/Tjidde.Logging.DesktopApp/Program.cs b/samples/Tjidde.Logging.DesktopApp/Program.cs index 1e70b18..7892dac 100644 --- a/samples/Tjidde.Logging.DesktopApp/Program.cs +++ b/samples/Tjidde.Logging.DesktopApp/Program.cs @@ -1,5 +1,4 @@ using Avalonia; -using Tjidde.Logging.DesktopApp.Logging; using Tjidde.Logging.DesktopApp.ViewModels; using Tjidde.Logging.Extensions; using Microsoft.Extensions.DependencyInjection; @@ -16,20 +15,16 @@ public static void Main(string[] args) { var services = new ServiceCollection(); - // Shared in-memory sink - var sink = new InMemoryLogSink(); - services.AddSingleton(sink); - - // Logging: Tjidde logger + in-memory capture + // Logging: Tjidde logger (console) + the built-in in-memory sink, which the UI reads services.AddLogging(builder => { builder.SetMinimumLevel(LogLevel.Trace); - builder.AddTjiddeLogger(options => - { - options.IncludeScopes = true; - }); - builder.Services.AddSingleton(sp => - new InMemoryLoggerProvider(sp.GetRequiredService())); + builder + .AddTjiddeLogger(options => + { + options.IncludeScopes = true; + }) + .AddTjiddeInMemorySink(); }); services.AddSingleton(); diff --git a/samples/Tjidde.Logging.DesktopApp/Tjidde.Logging.DesktopApp.csproj b/samples/Tjidde.Logging.DesktopApp/Tjidde.Logging.DesktopApp.csproj index ec20079..61b2100 100644 --- a/samples/Tjidde.Logging.DesktopApp/Tjidde.Logging.DesktopApp.csproj +++ b/samples/Tjidde.Logging.DesktopApp/Tjidde.Logging.DesktopApp.csproj @@ -10,12 +10,12 @@ - - - - - - + + + + + + diff --git a/samples/Tjidde.Logging.DesktopApp/ViewModels/MainViewModel.cs b/samples/Tjidde.Logging.DesktopApp/ViewModels/MainViewModel.cs index d080bca..90d610c 100644 --- a/samples/Tjidde.Logging.DesktopApp/ViewModels/MainViewModel.cs +++ b/samples/Tjidde.Logging.DesktopApp/ViewModels/MainViewModel.cs @@ -3,8 +3,8 @@ using System.ComponentModel; using System.Runtime.CompilerServices; using Tjidde.Logging.Context; -using Tjidde.Logging.DesktopApp.Logging; using Tjidde.Logging.Extensions; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Logging; namespace Tjidde.Logging.DesktopApp.ViewModels; @@ -16,7 +16,9 @@ public sealed class MainViewModel : INotifyPropertyChanged private string _customer = string.Empty; private string _message = string.Empty; - private LogLevel _selectedLevel = LogLevel.Information; + private const string MetricsLevel = "Metrics"; + + private string _selectedLevel = nameof(LogLevel.Information); private bool _includeException; private bool _includeInner; private string _exceptionMessage = "Something went wrong"; @@ -25,11 +27,12 @@ public MainViewModel(ILogger logger, InMemoryLogSink sink) { _logger = logger; _sink = sink; - _sink.OnChanged += OnSinkChanged; + _sink.EntryAdded += (_, _) => OnSinkChanged(); + _sink.Cleared += (_, _) => OnSinkChanged(); RefreshEntries(); } - public ObservableCollection Entries { get; } = new(); + public ObservableCollection Entries { get; } = new(); public string Customer { @@ -43,7 +46,7 @@ public string Message set { _message = value; OnPropertyChanged(); } } - public LogLevel SelectedLevel + public string SelectedLevel { get => _selectedLevel; set { _selectedLevel = value; OnPropertyChanged(); } @@ -67,15 +70,16 @@ public string ExceptionMessage set { _exceptionMessage = value; OnPropertyChanged(); } } - public LogLevel[] LogLevels { get; } = + // "Metrics" is not a log level: it is logged with LogMetrics (Information + MetricsEventId). + public string[] LogLevels { get; } = [ - LogLevel.Trace, - LogLevel.Debug, - LogLevel.Information, - LogLevel.Warning, - LogLevel.Error, - LogLevel.Critical, - MetricsLoggerExtensions.Metrics + nameof(LogLevel.Trace), + nameof(LogLevel.Debug), + nameof(LogLevel.Information), + nameof(LogLevel.Warning), + nameof(LogLevel.Error), + nameof(LogLevel.Critical), + MetricsLevel ]; public void SendLog() @@ -94,7 +98,10 @@ public void SendLog() string.IsNullOrWhiteSpace(_exceptionMessage) ? "Sample exception" : _exceptionMessage, inner); } - _logger.Log(_selectedLevel, ex, "{Message}", _message.Trim()); + if (_selectedLevel == MetricsLevel) + _logger.LogMetrics(ex, "{Message}", _message.Trim()); + else + _logger.Log(Enum.Parse(_selectedLevel), ex, "{Message}", _message.Trim()); CustomerContext.Clear(); } @@ -110,7 +117,7 @@ private void OnSinkChanged() private void RefreshEntries() { - var entries = _sink.GetEntries(); + var entries = _sink.GetSnapshot(); Entries.Clear(); foreach (var e in entries.Reverse()) Entries.Add(e); diff --git a/samples/Tjidde.Logging.DesktopApp/Views/MainWindow.axaml b/samples/Tjidde.Logging.DesktopApp/Views/MainWindow.axaml index 72f9adc..91186f8 100644 --- a/samples/Tjidde.Logging.DesktopApp/Views/MainWindow.axaml +++ b/samples/Tjidde.Logging.DesktopApp/Views/MainWindow.axaml @@ -1,8 +1,9 @@ @@ -26,7 +27,7 @@ @@ -43,7 +44,7 @@ @@ -96,7 +97,7 @@ - + - + @@ -118,13 +119,13 @@ VerticalAlignment="Center"/> - - - _entries = new(); - - public event Action? OnChanged; - - public void Add(LogEntry entry) - { - _entries.Enqueue(entry); - OnChanged?.Invoke(); - } - - public IReadOnlyList GetEntries() => _entries.ToArray(); - - public void Clear() - { - while (_entries.TryDequeue(out _)) { } - OnChanged?.Invoke(); - } -} - -[ProviderAlias("InMemory")] -public sealed class InMemoryLoggerProvider : ILoggerProvider -{ - private readonly InMemoryLogSink _sink; - - public InMemoryLoggerProvider(InMemoryLogSink sink) => _sink = sink; - - public ILogger CreateLogger(string categoryName) => new InMemoryLogger(categoryName, _sink); - - public void Dispose() { } -} - -internal sealed class InMemoryLogger : ILogger -{ - private readonly string _category; - private readonly InMemoryLogSink _sink; - - public InMemoryLogger(string category, InMemoryLogSink sink) - { - _category = category; - _sink = sink; - } - - public IDisposable? BeginScope(TState state) where TState : notnull => null; - - public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; - - public void Log(LogLevel logLevel, EventId eventId, TState state, - Exception? exception, Func formatter) - { - if (!IsEnabled(logLevel)) return; - - var message = formatter(state, exception); - var exDetails = exception is not null ? new ExceptionFormatter().Format(exception) : null; - - _sink.Add(new LogEntry - { - Timestamp = DateTimeOffset.Now, - Level = logLevel, - Category = _category, - FormattedMessage = message, - ExceptionDetails = exDetails - }); - } -} diff --git a/samples/Tjidde.Logging.TuiApp/Models/LogEntryLine.cs b/samples/Tjidde.Logging.TuiApp/Models/LogEntryLine.cs index 2b4a235..c795de7 100644 --- a/samples/Tjidde.Logging.TuiApp/Models/LogEntryLine.cs +++ b/samples/Tjidde.Logging.TuiApp/Models/LogEntryLine.cs @@ -1,38 +1,39 @@ -using Tjidde.Logging.TuiApp.Logging; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Logging; namespace Tjidde.Logging.TuiApp.Models; public sealed class LogEntryLine { - public LogEntry Entry { get; } + public TjiddeLogEntry Entry { get; } - public LogEntryLine(LogEntry entry) => Entry = entry; + public LogEntryLine(TjiddeLogEntry entry) => Entry = entry; public string GetStyledString() { + // Metrics entries are recognized by their event ID (MetricsEventId), not by a log level. var color = Entry.Level switch { + _ when Entry.IsMetrics => "cyan", LogLevel.Trace => "magenta", LogLevel.Debug => "gray", LogLevel.Information => "white", LogLevel.Warning => "yellow", LogLevel.Error => "red", LogLevel.Critical => "brightred", - _ when (int)Entry.Level == 700 => "cyan", _ => "white" }; var levelStr = FormatLevel(); - return $"[{Entry.Timestamp:HH:mm:ss}] [{{color:{color}}}] {levelStr}: {Entry.FormattedMessage}"; + return $"[{Entry.Timestamp:HH:mm:ss}] [{{color:{color}}}] {levelStr}: {Entry.Message}"; } public override string ToString() { var levelStr = FormatLevel(); - return $"[{Entry.Timestamp:HH:mm:ss}] {levelStr}: {Entry.FormattedMessage}"; + return $"[{Entry.Timestamp:HH:mm:ss}] {levelStr}: {Entry.Message}"; } private string FormatLevel() => - Entry.Level == (LogLevel)700 ? "METRICS" : Entry.Level.ToString().ToUpper(); + Entry.IsMetrics ? "METRICS" : Entry.Level.ToString().ToUpper(); } diff --git a/samples/Tjidde.Logging.TuiApp/Program.cs b/samples/Tjidde.Logging.TuiApp/Program.cs index c45cb11..cb3e658 100644 --- a/samples/Tjidde.Logging.TuiApp/Program.cs +++ b/samples/Tjidde.Logging.TuiApp/Program.cs @@ -1,5 +1,4 @@ using Tjidde.Logging.Extensions; -using Tjidde.Logging.TuiApp.Logging; using Tjidde.Logging.TuiApp.Services; using Tjidde.Logging.TuiApp.Views; using Microsoft.Extensions.DependencyInjection; @@ -26,19 +25,19 @@ static void Main(string[] args) private static ServiceProvider ConfigureServices() { var colorScheme = CreateColorScheme(); - var sink = new InMemoryLogSink(); - var services = new ServiceCollection(); - services.AddSingleton(sink); services.AddSingleton(colorScheme); services.AddSingleton(); services.AddSingleton(); - services.AddSingleton(new InMemoryLoggerProvider(sink)); + // Entries go to the built-in in-memory sink, which the log pane reads. The console sink is off: + // console output would draw over the terminal UI. services.AddLogging(builder => { - builder.AddTjiddeLogger(); + builder + .AddTjiddeLogger(options => options.WriteToConsole = false) + .AddTjiddeInMemorySink(); }); return services.BuildServiceProvider(); diff --git a/samples/Tjidde.Logging.TuiApp/Services/ILogService.cs b/samples/Tjidde.Logging.TuiApp/Services/ILogService.cs index 4bf7353..c7a2d2b 100644 --- a/samples/Tjidde.Logging.TuiApp/Services/ILogService.cs +++ b/samples/Tjidde.Logging.TuiApp/Services/ILogService.cs @@ -4,7 +4,8 @@ namespace Tjidde.Logging.TuiApp.Services; public interface ILogService { - void SendLog(string message, LogLevel level, string? customer, Exception? exception); + /// Logs at , or as a metrics entry (LogMetrics) when is set. + void SendLog(string message, LogLevel level, string? customer, Exception? exception, bool metrics = false); IReadOnlyList GetFormattedEntries(); void ClearLogs(); event Action? LogsChanged; diff --git a/samples/Tjidde.Logging.TuiApp/Services/LogService.cs b/samples/Tjidde.Logging.TuiApp/Services/LogService.cs index c1175ac..7d56186 100644 --- a/samples/Tjidde.Logging.TuiApp/Services/LogService.cs +++ b/samples/Tjidde.Logging.TuiApp/Services/LogService.cs @@ -1,5 +1,6 @@ using Tjidde.Logging.Context; -using Tjidde.Logging.TuiApp.Logging; +using Tjidde.Logging.Extensions; +using Tjidde.Logging.Sinks; using Tjidde.Logging.TuiApp.Models; using Microsoft.Extensions.Logging; @@ -16,15 +17,19 @@ public LogService(ILogger logger, InMemoryLogSink sink) { _logger = logger; _sink = sink; - _sink.OnChanged += () => LogsChanged?.Invoke(); + _sink.EntryAdded += (_, _) => LogsChanged?.Invoke(); + _sink.Cleared += (_, _) => LogsChanged?.Invoke(); } - public void SendLog(string message, LogLevel level, string? customer, Exception? exception) + public void SendLog(string message, LogLevel level, string? customer, Exception? exception, bool metrics = false) { CustomerContext.Set(customer); try { - _logger.Log(level, exception, "{Message}", message); + if (metrics) + _logger.LogMetrics(exception, "{Message}", message); + else + _logger.Log(level, exception, "{Message}", message); } finally { @@ -33,7 +38,7 @@ public void SendLog(string message, LogLevel level, string? customer, Exception? } public IReadOnlyList GetFormattedEntries() => - _sink.GetEntries() + _sink.GetSnapshot() .Reverse() .Select(e => new LogEntryLine(e).GetStyledString()) .ToList(); diff --git a/samples/Tjidde.Logging.TuiApp/Tjidde.Logging.TuiApp.csproj b/samples/Tjidde.Logging.TuiApp/Tjidde.Logging.TuiApp.csproj index 8239eb9..39f5f7b 100644 --- a/samples/Tjidde.Logging.TuiApp/Tjidde.Logging.TuiApp.csproj +++ b/samples/Tjidde.Logging.TuiApp/Tjidde.Logging.TuiApp.csproj @@ -5,8 +5,8 @@ - - + + diff --git a/samples/Tjidde.Logging.TuiApp/Views/MainView.cs b/samples/Tjidde.Logging.TuiApp/Views/MainView.cs index 30aa601..8780837 100644 --- a/samples/Tjidde.Logging.TuiApp/Views/MainView.cs +++ b/samples/Tjidde.Logging.TuiApp/Views/MainView.cs @@ -102,13 +102,15 @@ private FrameView CreateLeftPane() var customer = txtCustomer.Text.ToString(); CustomerContext.Set(customer); var level = ParseLogLevel(comboLevel.SelectedItem); + var metrics = comboLevel.SelectedItem == MetricsIndex; var ex = BuildException(chkException.Checked, txtExMsg.Text.ToString(), chkInner.Checked); _logService.SendLog( msg.Trim(), level, string.IsNullOrWhiteSpace(customer) ? null : customer.Trim(), - ex); + ex, + metrics); RefreshLogs(); }; @@ -178,6 +180,9 @@ private static void RegisterHelpKey(Toplevel top) }; } + // "Metrics" is not a log level: it is logged with LogMetrics (Information + MetricsEventId). + private const int MetricsIndex = 6; + private static LogLevel ParseLogLevel(int selectedIndex) => selectedIndex switch { 0 => LogLevel.Trace, @@ -186,7 +191,6 @@ private static void RegisterHelpKey(Toplevel top) 3 => LogLevel.Warning, 4 => LogLevel.Error, 5 => LogLevel.Critical, - 6 => (LogLevel)700, _ => LogLevel.Information }; diff --git a/src/Tjidde.Logging/Extensions/TjiddeLoggingBuilderExtensions.cs b/src/Tjidde.Logging/Extensions/TjiddeLoggingBuilderExtensions.cs index 782c9f7..d40f840 100644 --- a/src/Tjidde.Logging/Extensions/TjiddeLoggingBuilderExtensions.cs +++ b/src/Tjidde.Logging/Extensions/TjiddeLoggingBuilderExtensions.cs @@ -2,6 +2,7 @@ using Tjidde.Logging.Logging; using Tjidde.Logging.Masking; using Tjidde.Logging.Options; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; @@ -130,12 +131,72 @@ public static ILoggingBuilder UseIsolatedMaskedKeys(this ILoggingBuilder builder return builder; } + /// + /// Adds as an extra destination for Tjidde log entries. The sink is registered as a + /// singleton under its own type (so it can be injected) and as ; registering the same type + /// twice has no effect. Sinks are called synchronously on the logging thread and must be fast and thread-safe. + /// Sinks registered directly with services.AddSingleton<ILogSink, ...>() are used as well. + /// + /// The sink type, created by the container. + /// The . + /// The for chaining. + public static ILoggingBuilder AddTjiddeSink(this ILoggingBuilder builder) + where TSink : class, ILogSink + { + ArgumentNullException.ThrowIfNull(builder); + builder.Services.TryAddSingleton(); + builder.Services.TryAddEnumerable( + ServiceDescriptor.Singleton(services => services.GetRequiredService())); + return builder; + } + + /// + /// Adds as an extra destination for Tjidde log entries. The instance is registered as + /// and, unless that type is already registered, under , so it + /// can be injected. Sinks are called synchronously on the logging thread and must be fast and thread-safe. + /// The container does not dispose an instance passed here. + /// + /// The sink type. + /// The . + /// The sink instance. + /// The for chaining. + public static ILoggingBuilder AddTjiddeSink(this ILoggingBuilder builder, TSink sink) + where TSink : class, ILogSink + { + ArgumentNullException.ThrowIfNull(builder); + ArgumentNullException.ThrowIfNull(sink); + builder.Services.TryAddSingleton(sink); + builder.Services.AddSingleton(sink); + return builder; + } + + /// + /// Adds an that keeps the last entries, for example to + /// show them in a UI. Inject to read them. Calling it again has no effect. + /// + /// The . + /// The maximum number of entries kept. Default: . + /// The for chaining. + /// is less than 1. + public static ILoggingBuilder AddTjiddeInMemorySink(this ILoggingBuilder builder, int capacity = InMemoryLogSink.DefaultCapacity) + { + ArgumentNullException.ThrowIfNull(builder); + if (capacity < 1) + throw new ArgumentOutOfRangeException(nameof(capacity), capacity, "The capacity must be at least 1."); + + builder.Services.TryAddSingleton(_ => new InMemoryLogSink(capacity)); + builder.Services.TryAddEnumerable( + ServiceDescriptor.Singleton(services => services.GetRequiredService())); + return builder; + } + private static TjiddeLoggerProvider CreateProvider(IServiceProvider services) => new( services.GetRequiredService>(), services.GetRequiredService(), services.GetRequiredService(), - services.GetService() ?? TimeProvider.System); + services.GetService() ?? TimeProvider.System, + services.GetServices()); /// Signals an options change when the bound configuration section reloads. private sealed class ConfigurationSectionChangeTokenSource : IOptionsChangeTokenSource diff --git a/src/Tjidde.Logging/Formatting/ExceptionFormatter.cs b/src/Tjidde.Logging/Formatting/ExceptionFormatter.cs index 26400a3..522e057 100644 --- a/src/Tjidde.Logging/Formatting/ExceptionFormatter.cs +++ b/src/Tjidde.Logging/Formatting/ExceptionFormatter.cs @@ -36,14 +36,14 @@ private void AppendException(StringBuilder sb, Exception exception, int depth) if (sb.Length > 0 && depth == 0) sb.Append(' '); - sb.Append($"{prefix}[{exception.GetType().FullName}: {exception.Message}"); + sb.Append(prefix).Append('[').Append(exception.GetType().FullName).Append(": ").Append(exception.Message); if (_includeStackTrace && !string.IsNullOrWhiteSpace(exception.StackTrace)) { var frames = exception.StackTrace .Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries) .Select(l => l.Trim()); - sb.Append($" | StackTrace: {string.Join(" | ", frames)}"); + sb.Append(" | StackTrace: ").AppendJoin(" | ", frames); } sb.Append(']'); diff --git a/src/Tjidde.Logging/Logging/StringBuilderCache.cs b/src/Tjidde.Logging/Logging/StringBuilderCache.cs new file mode 100644 index 0000000..85d0185 --- /dev/null +++ b/src/Tjidde.Logging/Logging/StringBuilderCache.cs @@ -0,0 +1,37 @@ +using System.Text; + +namespace Tjidde.Logging.Logging; + +/// +/// One reusable per thread for building log lines. A nested log call on the same thread +/// (for example from a value's ToString()) finds the cache empty and gets a new builder, so builders are never +/// shared. Builders that grew beyond are not kept. +/// +internal static class StringBuilderCache +{ + private const int DefaultCapacity = 256; + private const int MaxCachedCapacity = 4096; + + [ThreadStatic] + private static StringBuilder? _cached; + + public static StringBuilder Acquire() + { + var sb = _cached; + if (sb is null) + return new StringBuilder(DefaultCapacity); + + _cached = null; + sb.Clear(); + return sb; + } + + public static string GetStringAndRelease(StringBuilder sb) + { + var result = sb.ToString(); + if (sb.Capacity <= MaxCachedCapacity) + _cached = sb; + + return result; + } +} diff --git a/src/Tjidde.Logging/Logging/TjiddeLogger.cs b/src/Tjidde.Logging/Logging/TjiddeLogger.cs index 3a51827..2e7e531 100644 --- a/src/Tjidde.Logging/Logging/TjiddeLogger.cs +++ b/src/Tjidde.Logging/Logging/TjiddeLogger.cs @@ -3,8 +3,12 @@ using Tjidde.Logging.Formatting; using Tjidde.Logging.Masking; using Tjidde.Logging.Options; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Logging; +using System.Buffers; using System.Diagnostics; +using System.Globalization; +using System.Text; using System.Text.Json; using System.Text.Json.Serialization; @@ -29,6 +33,7 @@ internal sealed class TjiddeLogger : ILogger private readonly TjiddeLoggerConfigurationHolder _configuration; private readonly ICustomerContextAccessor _customerContextAccessor; private readonly ConsoleLogProcessor _processor; + private readonly LogSinkDispatcher _sinks; private readonly TimeProvider _timeProvider; private IExternalScopeProvider? _scopeProvider; @@ -43,6 +48,7 @@ internal sealed class TjiddeLogger : ILogger /// Creates a logger that reads its settings from on every call, /// so a configuration change applies to this logger immediately. /// Timestamps come from (default: ). + /// Entries go to the console (unless is off) and to . /// public TjiddeLogger( string categoryName, @@ -50,8 +56,10 @@ public TjiddeLogger( ICustomerContextAccessor customerContextAccessor, ConsoleLogProcessor processor, IExternalScopeProvider? scopeProvider, - TimeProvider? timeProvider = null) + TimeProvider? timeProvider = null, + LogSinkDispatcher? sinks = null) { + _sinks = sinks ?? LogSinkDispatcher.Empty; _categoryName = categoryName; _configuration = configuration; _customerContextAccessor = customerContextAccessor; @@ -70,14 +78,16 @@ public TjiddeLogger( IExceptionFormatter exceptionFormatter, ConsoleLogProcessor processor, IExternalScopeProvider? scopeProvider, - TimeProvider? timeProvider = null) + TimeProvider? timeProvider = null, + LogSinkDispatcher? sinks = null) : this( categoryName, new TjiddeLoggerConfigurationHolder(new TjiddeLoggerConfiguration(options, masker, exceptionFormatter)), customerContextAccessor, processor, scopeProvider, - timeProvider) + timeProvider, + sinks) { } @@ -182,9 +192,20 @@ private void WriteEntry( ref string? message) { var customer = _customerContextAccessor.GetCustomerContext(); - var methodName = ResolveMethodName(config); - var maskedKeyNames = new List(); + // One pass over the scopes for both the MethodName scope and the scope texts (when scopes are included). + string? methodName; + List? scopes = null; + if (config.Options.IncludeScopes && _scopeProvider is not null) + (methodName, scopes) = ReadScopes(config, _scopeProvider); + else + methodName = null; + + if (methodName is null && config.Options.ResolveMethodNameFromStackTrace) + methodName = ExtractMethodFromStack(); + + // Allocated only when a property is actually masked. + List? maskedKeyNames = null; List>? properties = null; string? originalFormat = null; @@ -192,7 +213,10 @@ private void WriteEntry( // reach any output (text, JSON or OpenTelemetry) unmasked. if (state is IEnumerable> structuredState) { - properties = new List>(); + // FormattedLogValues and LoggerMessage state know their count ({OriginalFormat} included). + properties = structuredState is IReadOnlyCollection> { Count: > 0 } sized + ? new List>(sized.Count) + : new List>(); foreach (var kvp in structuredState) { if (kvp.Key.Equals("{OriginalFormat}", StringComparison.Ordinal)) @@ -201,23 +225,60 @@ private void WriteEntry( continue; } - properties.Add(new KeyValuePair(kvp.Key, SafeMaskPropertyValue(config, kvp.Key, kvp.Value, maskedKeyNames))); + properties.Add(new KeyValuePair(kvp.Key, SafeMaskPropertyValue(config, kvp.Key, kvp.Value, ref maskedKeyNames))); } } - message = RenderMessage(config, state, exception, formatter, originalFormat, properties, maskedKeyNames.Count > 0); + message = RenderMessage(config, state, exception, formatter, originalFormat, properties, maskedKeyNames is not null); - List? scopes = null; - if (config.Options.IncludeScopes && _scopeProvider is not null) - scopes = CollectScopes(config); + // Formatted (and masked) once, for the rendered line and the sinks. + var formattedException = exception is null ? null : FormatException(config, exception); var rendered = config.Options.OutputFormat == TjiddeLogOutputFormat.Json - ? BuildJsonLogLine(config, now, logLevel, eventId, methodName, customer, message, exception, scopes, maskedKeyNames, properties) - : BuildTextLogLine(config, now, logLevel, eventId, methodName, customer, message, exception, scopes, maskedKeyNames); + ? BuildJsonLogLine(config, now, logLevel, eventId, methodName, customer, message, formattedException, scopes, maskedKeyNames, properties) + : BuildTextLogLine(now, logLevel, eventId, methodName, customer, message, formattedException, scopes, maskedKeyNames); ExportToOpenTelemetry(config, now, logLevel, eventId, methodName, customer, message, exception, scopes, maskedKeyNames, properties); - _processor.Enqueue(rendered, config.Options.OutputFormat == TjiddeLogOutputFormat.Text ? GetColor(logLevel, eventId) : null); + Emit(config, now, logLevel, eventId, methodName, customer, message, formattedException, rendered); + } + + /// + /// Writes the rendered entry to the console (when is on) + /// and passes it to the sinks. Only masked data reaches either. + /// + private void Emit( + TjiddeLoggerConfiguration config, + DateTimeOffset timestamp, + LogLevel logLevel, + EventId eventId, + string? methodName, + string? customer, + string message, + string? formattedException, + string rendered) + { + var format = config.Options.OutputFormat; + if (config.Options.WriteToConsole) + _processor.Enqueue(rendered, format == TjiddeLogOutputFormat.Text ? GetColor(logLevel, eventId) : null); + + if (!_sinks.IsActive) + return; + + _sinks.Dispatch(new TjiddeLogEntry + { + Timestamp = timestamp, + Level = logLevel, + EventId = eventId, + Category = _categoryName, + ClassName = _className, + MethodName = methodName, + Customer = customer, + Message = message, + FormattedException = formattedException, + RenderedLine = rendered, + OutputFormat = format + }); } /// @@ -260,7 +321,7 @@ private void WriteFallbackEntry( $"[Log entry could not be rendered completely: {failure}] | Category: {_categoryName}"; } - _processor.Enqueue(line, config.Options.OutputFormat == TjiddeLogOutputFormat.Text ? GetColor(logLevel, eventId) : null); + Emit(config, now, logLevel, eventId, methodName: null, customer: null, message, formattedException: null, line); } catch (Exception) { @@ -273,7 +334,7 @@ private void WriteFallbackEntry( /// structured state yields its unrendered template, because the framework's formatter inserts raw /// (unmasked) values of sensitive properties. /// - private string? FallbackMessage(TjiddeLoggerConfiguration config, TState state, Exception? exception, Func formatter) + private static string? FallbackMessage(TjiddeLoggerConfiguration config, TState state, Exception? exception, Func formatter) { if (config.Options.EnableSensitiveDataMasking && state is IEnumerable> structuredState) { @@ -308,7 +369,7 @@ private void WriteFallbackEntry( } } - private string? TryMask(TjiddeLoggerConfiguration config, string? text) + private static string? TryMask(TjiddeLoggerConfiguration config, string? text) { if (text is null || !config.Options.EnableSensitiveDataMasking) return text; @@ -353,7 +414,7 @@ private static string SafeExceptionMessage(Exception exception) private static string Unserializable(object value) => $"[unserializable: {value.GetType().FullName}]"; - private string RenderMessage( + private static string RenderMessage( TjiddeLoggerConfiguration config, TState state, Exception? exception, @@ -386,11 +447,11 @@ private string RenderMessage( return config.Options.EnableSensitiveDataMasking ? config.Masker.MaskMessage(message) : message; } - private object? SafeMaskPropertyValue(TjiddeLoggerConfiguration config, string key, object? value, List maskedKeyNames) + private static object? SafeMaskPropertyValue(TjiddeLoggerConfiguration config, string key, object? value, ref List? maskedKeyNames) { try { - return MaskPropertyValue(config, key, value, maskedKeyNames); + return MaskPropertyValue(config, key, value, ref maskedKeyNames); } catch (Exception) { @@ -399,14 +460,14 @@ private string RenderMessage( } } - private object? MaskPropertyValue(TjiddeLoggerConfiguration config, string key, object? value, List maskedKeyNames) + private static object? MaskPropertyValue(TjiddeLoggerConfiguration config, string key, object? value, ref List? maskedKeyNames) { if (!config.Options.EnableSensitiveDataMasking) return value; if (config.Masker.IsSensitiveKey(key)) { - maskedKeyNames.Add(key); + (maskedKeyNames ??= []).Add(key); return config.Masker.MaskValue(key, value?.ToString() ?? string.Empty); } @@ -414,7 +475,7 @@ private string RenderMessage( return value is string text ? config.Masker.MaskMessage(text) : value; } - private string FormatException(TjiddeLoggerConfiguration config, Exception exception) + private static string FormatException(TjiddeLoggerConfiguration config, Exception exception) { string formatted; try @@ -441,7 +502,7 @@ private void ExportToOpenTelemetry( string message, Exception? exception, List? scopes, - List maskedKeyNames, + List? maskedKeyNames, List>? properties) { if (!config.Options.EnableOpenTelemetryExport) @@ -480,7 +541,7 @@ private void ExportToOpenTelemetry( string message, Exception? exception, List? scopes, - List maskedKeyNames, + List? maskedKeyNames, List>? properties) { yield return new KeyValuePair("log.category", _categoryName); @@ -511,7 +572,7 @@ private void ExportToOpenTelemetry( if (scopes is { Count: > 0 }) yield return new KeyValuePair("log.scopes", string.Join(" > ", scopes)); - if (maskedKeyNames.Count > 0) + if (maskedKeyNames is { Count: > 0 }) yield return new KeyValuePair("log.masked_fields", string.Join(",", maskedKeyNames)); if (properties is not null) @@ -522,30 +583,42 @@ private void ExportToOpenTelemetry( } private string BuildTextLogLine( - TjiddeLoggerConfiguration config, DateTimeOffset timestamp, LogLevel logLevel, EventId eventId, string? methodName, string? customer, string message, - Exception? exception, + string? formattedException, List? scopes, - List maskedKeyNames) + List? maskedKeyNames) { - var sb = new System.Text.StringBuilder(); - sb.Append(BuildLogLine(timestamp, FormatLogLevel(logLevel, eventId), _className, methodName, customer, message)); + // Written straight into one (reused) builder: no intermediate strings for the date, time and parts. + var sb = StringBuilderCache.Acquire(); + AppendLogLine(sb, timestamp, FormatLogLevel(logLevel, eventId), _className, methodName, customer, message); - if (maskedKeyNames.Count > 0) - sb.Append($" [Masked: {string.Join(", ", maskedKeyNames)}]"); + if (maskedKeyNames is { Count: > 0 }) + AppendJoined(sb.Append(" [Masked: "), ", ", maskedKeyNames).Append(']'); - if (exception is not null) - sb.Append($" | Exception: {FormatException(config, exception)}"); + if (formattedException is not null) + sb.Append(" | Exception: ").Append(formattedException); if (scopes is { Count: > 0 }) - sb.Append($" | Scopes: {string.Join(" > ", scopes)}"); + AppendJoined(sb.Append(" | Scopes: "), " > ", scopes); + + return StringBuilderCache.GetStringAndRelease(sb); + } + + private static StringBuilder AppendJoined(StringBuilder sb, string separator, List values) + { + for (var i = 0; i < values.Count; i++) + { + if (i > 0) + sb.Append(separator); + sb.Append(values[i]); + } - return sb.ToString(); + return sb; } private string BuildJsonLogLine( @@ -556,32 +629,208 @@ private string BuildJsonLogLine( string? methodName, string? customer, string message, - Exception? exception, + string? formattedException, List? scopes, - List maskedKeyNames, + List? maskedKeyNames, List>? properties) + { + // Each property value is serialized on its own first, so a value that cannot be serialized only affects itself. + object?[]? values = null; + if (properties is { Count: > 0 }) + { + values = new object?[properties.Count]; + for (var i = 0; i < values.Length; i++) + values[i] = ToSerializableValue(config, properties[i].Value); + } + + var line = new JsonLine( + timestamp.ToString("O"), message, FormatLogLevel(logLevel, eventId), _categoryName, _className, eventId, + customer, methodName, scopes is { Count: > 0 } ? scopes : null, maskedKeyNames is { Count: > 0 } ? maskedKeyNames : null, + formattedException, properties, values); + + try + { + return WriteJsonLine(line); + } + catch (Exception) + { + // The direct writer failed (for example a value nested too deeply): serialize as before, which either + // produces the same line or fails the same way. + return SerializeJsonLine(line); + } + } + + /// The parts of a JSON line; Values holds the serializable value of each property. + private readonly record struct JsonLine( + string Timestamp, + string Message, + string Level, + string Category, + string ClassName, + EventId EventId, + string? Customer, + string? Method, + List? Scopes, + List? MaskedFields, + string? Exception, + List>? Properties, + object?[]? Values); + + private static readonly JsonWriterOptions JsonLineWriterOptions = new() + { + // As JsonSerializer writes with JsonOptions: default encoder, not indented, same maximum depth. + Encoder = JsonOptions.Encoder, + Indented = JsonOptions.WriteIndented, + MaxDepth = JsonOptions.MaxDepth + }; + + [ThreadStatic] + private static ArrayBufferWriter? _cachedJsonBuffer; + + /// + /// Writes the line with a : the same JSON as , + /// without building dictionaries and without the serializer's per-value type lookups. + /// + private static string WriteJsonLine(in JsonLine line) + { + // Reused per thread; nothing in here calls user code, so a nested log call cannot reach it while in use. + var buffer = _cachedJsonBuffer ?? new ArrayBufferWriter(512); + _cachedJsonBuffer = null; + buffer.Clear(); + + try + { + using (var writer = new Utf8JsonWriter(buffer, JsonLineWriterOptions)) + { + writer.WriteStartObject(); + writer.WriteString("@timestamp", line.Timestamp); + writer.WriteString("message", line.Message); + writer.WriteString("level", line.Level); + writer.WriteString("category", line.Category); + writer.WriteString("class", line.ClassName); + writer.WriteNumber("eventId", line.EventId.Id); + writer.WriteString("eventName", line.EventId.Name); + writer.WriteString("customer", line.Customer); + writer.WriteString("method", line.Method); + WriteStringArray(writer, "scopes", line.Scopes); + WriteStringArray(writer, "maskedFields", line.MaskedFields); + writer.WriteString("exception", line.Exception); + + if (line.Properties is { Count: > 0 } properties) + { + writer.WriteStartObject("properties"); + for (var i = 0; i < properties.Count; i++) + { + // A repeated name keeps its first position and its last value, as the dictionary did. + var key = properties[i].Key; + if (IndexOfKey(properties, key, 0, i) >= 0) + continue; + + var last = i; + for (var j = i + 1; j < properties.Count; j++) + { + if (string.Equals(properties[j].Key, key, StringComparison.Ordinal)) + last = j; + } + + writer.WritePropertyName(key); + WriteValue(writer, line.Values![last]); + } + + writer.WriteEndObject(); + } + + writer.WriteEndObject(); + } + + return Encoding.UTF8.GetString(buffer.WrittenSpan); + } + finally + { + if (buffer.Capacity <= 16 * 1024) + _cachedJsonBuffer = buffer; + } + } + + private static int IndexOfKey(List> properties, string key, int start, int end) + { + for (var i = start; i < end; i++) + { + if (string.Equals(properties[i].Key, key, StringComparison.Ordinal)) + return i; + } + + return -1; + } + + private static void WriteStringArray(Utf8JsonWriter writer, string name, List? values) + { + if (values is null) + { + writer.WriteNull(name); + return; + } + + writer.WriteStartArray(name); + foreach (var value in values) + writer.WriteStringValue(value); + writer.WriteEndArray(); + } + + /// Writes a value produced by . + private static void WriteValue(Utf8JsonWriter writer, object? value) + { + switch (value) + { + case null: + writer.WriteNullValue(); + break; + case JsonElement element: + element.WriteTo(writer); + break; + case string text: + writer.WriteStringValue(text); + break; + case int number: + writer.WriteNumberValue(number); + break; + case long number: + writer.WriteNumberValue(number); + break; + case bool flag: + writer.WriteBooleanValue(flag); + break; + default: + // Not produced by ToSerializableValue; written by the serializer, as before. + JsonSerializer.Serialize(writer, value, value.GetType(), JsonOptions); + break; + } + } + + /// The original way to write the line: dictionaries serialized by . + private static string SerializeJsonLine(in JsonLine line) { var payload = new Dictionary { - ["@timestamp"] = timestamp.ToString("O"), - ["message"] = message, - ["level"] = FormatLogLevel(logLevel, eventId), - ["category"] = _categoryName, - ["class"] = _className, - ["eventId"] = eventId.Id, - ["eventName"] = eventId.Name, - ["customer"] = customer, - ["method"] = methodName, - ["scopes"] = scopes is { Count: > 0 } ? scopes : null, - ["maskedFields"] = maskedKeyNames.Count > 0 ? maskedKeyNames : null, - ["exception"] = exception is null ? null : FormatException(config, exception) + ["@timestamp"] = line.Timestamp, + ["message"] = line.Message, + ["level"] = line.Level, + ["category"] = line.Category, + ["class"] = line.ClassName, + ["eventId"] = line.EventId.Id, + ["eventName"] = line.EventId.Name, + ["customer"] = line.Customer, + ["method"] = line.Method, + ["scopes"] = line.Scopes, + ["maskedFields"] = line.MaskedFields, + ["exception"] = line.Exception }; - if (properties is { Count: > 0 }) + if (line.Properties is { Count: > 0 } properties) { var propertyMap = new Dictionary(); - foreach (var kvp in properties) - propertyMap[kvp.Key] = ToSerializableValue(config, kvp.Value); + for (var i = 0; i < properties.Count; i++) + propertyMap[properties[i].Key] = line.Values![i]; payload["properties"] = propertyMap; } @@ -593,10 +842,18 @@ private string BuildJsonLogLine( /// throwing getter, too deep) only affects itself: it falls back to ToString(), or to /// [unserializable: TypeName] when that throws too. /// - private object? ToSerializableValue(TjiddeLoggerConfiguration config, object? value) + private static object? ToSerializableValue(TjiddeLoggerConfiguration config, object? value) { - if (value is null) - return null; + // Values that serialize to themselves are written directly, which gives the same JSON as their element. + // Strings with surrogates go through the serializer, whose round trip may change unpaired surrogates. + switch (value) + { + case null: + return null; + case string text when !ContainsSurrogate(text): + case int or long or bool: + return value; + } try { @@ -609,7 +866,27 @@ private string BuildJsonLogLine( } } - private static string BuildLogLine( + private static bool ContainsSurrogate(string text) + { +#if NET8_0_OR_GREATER + return text.AsSpan().IndexOfAnyInRange('\uD800', '\uDFFF') >= 0; +#else + foreach (var c in text) + { + if (char.IsSurrogate(c)) + return true; + } + + return false; +#endif + } + + /// + /// Appends {date}: {time}: [{level}] Class=>{className}[ Method=>{method}]: [Client=>{customer}: ]{message}. + /// The date and time are formatted with the current culture, like . + /// + private static void AppendLogLine( + StringBuilder sb, DateTimeOffset timestamp, string level, string className, @@ -617,12 +894,23 @@ private static string BuildLogLine( string? customer, string message) { - var date = timestamp.ToString("yyyy-MM-dd"); - var time = timestamp.ToString("HH:mm:ss"); - var method = string.IsNullOrWhiteSpace(methodName) ? string.Empty : $" Method=>{methodName}"; - var customerPart = string.IsNullOrWhiteSpace(customer) ? string.Empty : $"Client=>{customer}: "; + sb.Append(timestamp.ToString("yyyy-MM-dd", CultureInfo.CurrentCulture)) + .Append(": ") + .Append(timestamp.ToString("HH:mm:ss", CultureInfo.CurrentCulture)) + .Append(": [") + .Append(level) + .Append("] Class=>") + .Append(className); + + if (!string.IsNullOrWhiteSpace(methodName)) + sb.Append(" Method=>").Append(methodName); + + sb.Append(": "); + + if (!string.IsNullOrWhiteSpace(customer)) + sb.Append("Client=>").Append(customer).Append(": "); - return $"{date}: {time}: [{level}] Class=>{className}{method}: {customerPart}{message}"; + sb.Append(message); } private static string FormatLogLevel(LogLevel logLevel, EventId eventId) => logLevel switch @@ -637,27 +925,83 @@ _ when MetricsLoggerExtensions.IsMetricsEntry(logLevel, eventId) => "METRICS", _ => "???" }; - private string? ResolveMethodName(TjiddeLoggerConfiguration config) - => ExtractMethodFromScope(config) - ?? (config.Options.ResolveMethodNameFromStackTrace ? ExtractMethodFromStack() : null); + /// + /// Reads the active scopes once: the method name from the innermost MethodName scope value, and the scope + /// texts for the output (masked, without MethodName). Scopes is when no scope adds text. + /// + private static (string? MethodName, List? Scopes) ReadScopes(TjiddeLoggerConfiguration config, IExternalScopeProvider scopeProvider) + { + // Reused per thread so a call without scopes allocates nothing; a nested log call (from a scope value's + // ToString) finds the cache empty and uses its own reader. + var reader = ScopeReader.Cached ?? new ScopeReader(); + ScopeReader.Cached = null; + + reader.Config = config; + try + { + scopeProvider.ForEachScope(static (scope, r) => r.Read(scope), reader); + return (reader.MethodName, reader.Scopes); + } + finally + { + reader.Reset(); + ScopeReader.Cached = reader; + } + } - private string? ExtractMethodFromScope(TjiddeLoggerConfiguration config) + private sealed class ScopeReader { - if (!config.Options.IncludeScopes || _scopeProvider is null) - return null; + [ThreadStatic] + public static ScopeReader? Cached; + + public TjiddeLoggerConfiguration Config = null!; + public string? MethodName; + public List? Scopes; + + public void Reset() + { + Config = null!; + MethodName = null; + Scopes = null; + } - string? methodName = null; - _scopeProvider.ForEachScope((scope, _) => + public void Read(object? scope) { - if (scope is not IEnumerable> kvps) return; - foreach (var kvp in kvps) + // The method name: an enumeration that throws here fails the entry (it is not caught), as before. + if (scope is IEnumerable> methodScope) { - if (kvp.Key.Equals("MethodName", StringComparison.OrdinalIgnoreCase) && kvp.Value is string m) - methodName = m; + foreach (var kvp in methodScope) + { + if (kvp.Key.Equals("MethodName", StringComparison.OrdinalIgnoreCase) && kvp.Value is string m) + MethodName = m; + } } - }, (object?)null); - return methodName; + // The scope text: a scope whose enumeration throws is skipped instead of failing the whole entry. + try + { + switch (scope) + { + case string s when !string.IsNullOrWhiteSpace(s): + (Scopes ??= []).Add(Config.Options.EnableSensitiveDataMasking ? Config.Masker.MaskMessage(s) : s); + break; + case IEnumerable> kvps: + { + foreach (var kvp in kvps) + { + if (!kvp.Key.Equals("MethodName", StringComparison.OrdinalIgnoreCase)) + (Scopes ??= []).Add(FormatScopeProperty(Config, kvp.Key, kvp.Value)); + } + + break; + } + } + } + catch (Exception) + { + (Scopes ??= []).Add($"[unserializable scope: {scope?.GetType().FullName}]"); + } + } } private static string? ExtractMethodFromStack() @@ -691,7 +1035,7 @@ _ when MetricsLoggerExtensions.IsMetricsEntry(logLevel, eventId) => "METRICS", return null; } - private string FormatScopeProperty(TjiddeLoggerConfiguration config, string key, object? value) + private static string FormatScopeProperty(TjiddeLoggerConfiguration config, string key, object? value) { var raw = SafeToString(value) ?? string.Empty; if (!config.Options.EnableSensitiveDataMasking) @@ -703,35 +1047,6 @@ private string FormatScopeProperty(TjiddeLoggerConfiguration config, string key, return $"{key}={text}"; } - private List CollectScopes(TjiddeLoggerConfiguration config) - { - var scopes = new List(); - _scopeProvider?.ForEachScope((scope, list) => - { - try - { - switch (scope) - { - case string s when !string.IsNullOrWhiteSpace(s): - list.Add(config.Options.EnableSensitiveDataMasking ? config.Masker.MaskMessage(s) : s); - break; - case IEnumerable> kvps: - { - list.AddRange(from kvp in kvps where !kvp.Key.Equals("MethodName", StringComparison.OrdinalIgnoreCase) select FormatScopeProperty(config, kvp.Key, kvp.Value)); - - break; - } - } - } - catch (Exception) - { - // A scope whose enumeration throws is skipped instead of failing the whole entry. - list.Add($"[unserializable scope: {scope?.GetType().FullName}]"); - } - }, scopes); - return scopes; - } - private static ConsoleColor GetColor(LogLevel logLevel, EventId eventId) => logLevel switch { _ when MetricsLoggerExtensions.IsMetricsEntry(logLevel, eventId) => ConsoleColor.Magenta, diff --git a/src/Tjidde.Logging/Logging/TjiddeLoggerProvider.cs b/src/Tjidde.Logging/Logging/TjiddeLoggerProvider.cs index d56b34b..d57c5db 100644 --- a/src/Tjidde.Logging/Logging/TjiddeLoggerProvider.cs +++ b/src/Tjidde.Logging/Logging/TjiddeLoggerProvider.cs @@ -3,6 +3,7 @@ using Tjidde.Logging.Formatting; using Tjidde.Logging.Masking; using Tjidde.Logging.Options; +using Tjidde.Logging.Sinks; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -23,6 +24,7 @@ public sealed class TjiddeLoggerProvider : ILoggerProvider, ISupportExternalScop private readonly object _sync = new(); private readonly ConcurrentDictionary _loggers = new(StringComparer.OrdinalIgnoreCase); private readonly ConsoleLogProcessor _processor = new(); + private readonly LogSinkDispatcher _sinks; private IExternalScopeProvider _scopeProvider = NoopExternalScopeProvider.Instance; private bool _disposed; @@ -48,9 +50,34 @@ public TjiddeLoggerProvider( ICustomerContextAccessor customerContextAccessor, IMaskedKeysAccessor maskedKeysAccessor, TimeProvider timeProvider) + : this(optionsMonitor, customerContextAccessor, maskedKeysAccessor, timeProvider, sinks: null) + { + } + + /// + /// Initializes a new instance of that takes its timestamps from + /// and passes every entry to besides the console. + /// + /// The options; changes apply to existing loggers immediately. + /// Supplies the customer of each entry. + /// Supplies the runtime masked keys. + /// The clock for timestamps. + /// + /// Extra destinations for the entries, called synchronously in this order. means none. + /// A sink that throws is ignored and does not affect the others. + /// + /// is . + public TjiddeLoggerProvider( + IOptionsMonitor optionsMonitor, + ICustomerContextAccessor customerContextAccessor, + IMaskedKeysAccessor maskedKeysAccessor, + TimeProvider timeProvider, + IEnumerable? sinks) { ArgumentNullException.ThrowIfNull(timeProvider); + _sinks = new LogSinkDispatcher(sinks); + _customerContextAccessor = customerContextAccessor; _maskedKeysAccessor = maskedKeysAccessor; _timeProvider = timeProvider; @@ -109,7 +136,7 @@ public void Dispose() { } } private TjiddeLogger CreateLoggerInstance(string categoryName) - => new(categoryName, _configuration, _customerContextAccessor, _processor, _scopeProvider, _timeProvider); + => new(categoryName, _configuration, _customerContextAccessor, _processor, _scopeProvider, _timeProvider, _sinks); private void OnOptionsChanged(TjiddeLoggerOptions options, string? name) { diff --git a/src/Tjidde.Logging/Masking/SensitiveDataMasker.cs b/src/Tjidde.Logging/Masking/SensitiveDataMasker.cs index a9febd7..41410fe 100644 --- a/src/Tjidde.Logging/Masking/SensitiveDataMasker.cs +++ b/src/Tjidde.Logging/Masking/SensitiveDataMasker.cs @@ -1,3 +1,6 @@ +#if NET9_0_OR_GREATER +using System.Buffers; +#endif using System.Text.RegularExpressions; namespace Tjidde.Logging.Masking; @@ -171,9 +174,16 @@ private sealed class KeySet private const RegexOptions PatternOptions = RegexOptions.IgnoreCase; private readonly HashSet _normalizedKeys = new(StringComparer.OrdinalIgnoreCase); - private readonly List<(Regex Pattern, MatchEvaluator Mask)> _patterns = []; + private readonly List _patterns = []; +#if NET9_0_OR_GREATER + // All ASCII keys at once: one vectorized scan tells whether a message can match any of their patterns. + private readonly SearchValues? _asciiKeySearch; +#endif + private readonly bool _hasNonAsciiKey; private readonly string[] _literals; private readonly string _placeholder; + private readonly MatchEvaluator _maskSeparatedValue; + private readonly MatchEvaluator _maskSpacedValue; private readonly object? _sourceReference; private readonly bool _hasSource; private readonly HashSet _sourceKeys; @@ -187,6 +197,8 @@ public KeySet( object? sourceReference = null) { _placeholder = placeholder; + _maskSeparatedValue = MaskSeparatedValue; + _maskSpacedValue = MaskSpacedValue; _literals = literals.Where(literal => !string.IsNullOrWhiteSpace(literal)).ToArray(); _sourceReference = sourceReference; _hasSource = source is not null; @@ -203,17 +215,45 @@ public KeySet( // "password=value", "password: value", "\"password\": \"value\"", "Authorization: Bearer value". // Quoted values are masked up to the closing quote, so values with spaces are masked completely. - _patterns.Add((new Regex( + var separated = new Regex( $@"(?{escaped}[""']?\s*[:=]\s*)(?:(?[""'])(?:\\.|(?!\k)[^\\\r\n])*\k|(?(?:{AuthSchemes})\s+)?\S+)", PatternOptions, - matchTimeout), MaskSeparatedValue)); + matchTimeout); // "password somevalue" (value must be 4+ chars to avoid natural language) - _patterns.Add((new Regex( + var spaced = new Regex( $@"(?{escaped}\s+[""']?(?:(?:{AuthSchemes})\s+)?)\S{{4,}}", PatternOptions, - matchTimeout), MaskSpacedValue)); + matchTimeout); + + var isAscii = IsAscii(key); + _hasNonAsciiKey |= !isAscii; + _patterns.Add(new KeyPatterns(key, isAscii, separated, spaced)); } + +#if NET9_0_OR_GREATER + var asciiKeys = _patterns.Where(p => p.KeyIsAscii).Select(p => p.Key).Distinct(StringComparer.OrdinalIgnoreCase).ToArray(); + if (asciiKeys.Length > 0) + _asciiKeySearch = SearchValues.Create(asciiKeys, StringComparison.OrdinalIgnoreCase); +#endif + } + + /// The patterns of one key; every match of either pattern contains the key itself. + private sealed record KeyPatterns(string Key, bool KeyIsAscii, Regex Separated, Regex Spaced); + + private static bool IsAscii(string text) + { +#if NET8_0_OR_GREATER + return System.Text.Ascii.IsValid(text); +#else + foreach (var c in text) + { + if (c > '\u007F') + return false; + } + + return true; +#endif } public bool Contains(string normalizedKey) => _normalizedKeys.Contains(normalizedKey); @@ -228,11 +268,28 @@ public bool IsBuiltFrom(IReadOnlyCollection keys, bool referenceMeansUnc public string MaskPatterns(string message) { + if (_patterns.Count == 0) + return message; + try { var result = message; - foreach (var (pattern, mask) in _patterns) - result = pattern.Replace(result, mask); + + // Every match contains its key, so a key that does not occur in the message cannot match and its + // patterns are skipped. The ordinal check only rules a key out for ASCII text and an ASCII key: there it + // agrees with the patterns' IgnoreCase matching, while non-ASCII text can match case-insensitively in + // ways an ordinal comparison does not (for example the Kelvin sign and "k"); those always run the patterns. + var resultIsAscii = IsAscii(result); +#if NET9_0_OR_GREATER + if (resultIsAscii && !_hasNonAsciiKey && (_asciiKeySearch is null || !result.AsSpan().ContainsAny(_asciiKeySearch))) + return result; +#endif + + foreach (var key in _patterns) + { + result = Replace(key.Separated, result, _maskSeparatedValue, key, ref resultIsAscii); + result = Replace(key.Spaced, result, _maskSpacedValue, key, ref resultIsAscii); + } return result; } @@ -243,6 +300,20 @@ public string MaskPatterns(string message) } } + private static string Replace(Regex pattern, string text, MatchEvaluator mask, KeyPatterns key, ref bool textIsAscii) + { + if (textIsAscii && key.KeyIsAscii && !text.Contains(key.Key, StringComparison.OrdinalIgnoreCase)) + return text; + + var replaced = pattern.Replace(text, mask); + + // Regex.Replace returns the same instance when nothing matched; the placeholder may be non-ASCII. + if (!ReferenceEquals(replaced, text)) + textIsAscii = IsAscii(replaced); + + return replaced; + } + public string MaskLiterals(string message) { var result = message; diff --git a/src/Tjidde.Logging/Options/TjiddeLogOutputFormat.cs b/src/Tjidde.Logging/Options/TjiddeLogOutputFormat.cs index d8825c1..ef2c6af 100644 --- a/src/Tjidde.Logging/Options/TjiddeLogOutputFormat.cs +++ b/src/Tjidde.Logging/Options/TjiddeLogOutputFormat.cs @@ -5,6 +5,9 @@ namespace Tjidde.Logging.Options; /// public enum TjiddeLogOutputFormat { + /// One human-readable line per entry: YYYY-MM-DD: HH:mm:ss: [LEVEL] Class=>... : message. Text = 0, + + /// One JSON object per entry, for log collectors. Json = 1 } diff --git a/src/Tjidde.Logging/Options/TjiddeLoggerOptions.cs b/src/Tjidde.Logging/Options/TjiddeLoggerOptions.cs index a559af8..2ceda7a 100644 --- a/src/Tjidde.Logging/Options/TjiddeLoggerOptions.cs +++ b/src/Tjidde.Logging/Options/TjiddeLoggerOptions.cs @@ -13,6 +13,14 @@ public sealed class TjiddeLoggerOptions /// public TjiddeLogOutputFormat OutputFormat { get; set; } = TjiddeLogOutputFormat.Text; + /// + /// Whether entries are written to the console. Set to to write only to the registered + /// s (for example in a desktop or terminal UI). A change applies immediately when the + /// options reload. OpenTelemetry export is not affected. + /// Default: true. + /// + public bool WriteToConsole { get; set; } = true; + internal const string MinimumLevelObsoleteMessage = "Use the standard Microsoft.Extensions.Logging filters instead: Logging:Tjidde:LogLevel in appsettings.json " + "(or AddFilter(...) in code). This option will be removed in 2.0."; diff --git a/src/Tjidde.Logging/PublicAPI.Shipped.txt b/src/Tjidde.Logging/PublicAPI.Shipped.txt new file mode 100644 index 0000000..2d9b2c2 --- /dev/null +++ b/src/Tjidde.Logging/PublicAPI.Shipped.txt @@ -0,0 +1,86 @@ +#nullable enable +static readonly Tjidde.Logging.Extensions.MetricsLoggerExtensions.Metrics -> Microsoft.Extensions.Logging.LogLevel +static Tjidde.Logging.Context.CustomerContext.Clear() -> void +static Tjidde.Logging.Context.CustomerContext.Current.get -> string? +static Tjidde.Logging.Context.CustomerContext.Set(string? customerIdentifier) -> void +static Tjidde.Logging.Extensions.MethodScopeLoggerExtensions.BeginMethodScope(this Microsoft.Extensions.Logging.ILogger! logger, string! methodName = "") -> System.IDisposable? +static Tjidde.Logging.Extensions.MetricsLoggerExtensions.LogMetrics(this Microsoft.Extensions.Logging.ILogger! logger, Microsoft.Extensions.Logging.EventId eventId, string! message, params object?[]! args) -> void +static Tjidde.Logging.Extensions.MetricsLoggerExtensions.LogMetrics(this Microsoft.Extensions.Logging.ILogger! logger, string! message, params object?[]! args) -> void +static Tjidde.Logging.Extensions.MetricsLoggerExtensions.LogMetrics(this Microsoft.Extensions.Logging.ILogger! logger, System.Exception? exception, string! message, params object?[]! args) -> void +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeLogger(this Microsoft.Extensions.Logging.ILoggingBuilder! builder) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeLogger(this Microsoft.Extensions.Logging.ILoggingBuilder! builder, Microsoft.Extensions.Configuration.IConfiguration! configuration, string! sectionPath = "TjiddeLogger") -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeLogger(this Microsoft.Extensions.Logging.ILoggingBuilder! builder, Microsoft.Extensions.Configuration.IConfigurationSection! configurationSection) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeLogger(this Microsoft.Extensions.Logging.ILoggingBuilder! builder, System.Action! configure) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.UseTjiddeJsonFormat(this Microsoft.Extensions.Logging.ILoggingBuilder! builder) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.UseTjiddeTextFormat(this Microsoft.Extensions.Logging.ILoggingBuilder! builder) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Masking.MaskedKeysContext.Add(params string![]! keys) -> void +static Tjidde.Logging.Masking.MaskedKeysContext.Clear() -> void +static Tjidde.Logging.Masking.MaskedKeysContext.GetKeys() -> System.Collections.Generic.IReadOnlyCollection! +static Tjidde.Logging.Masking.MaskedKeysContext.Remove(params string![]! keys) -> void +Tjidde.Logging.Context.AsyncLocalCustomerContextAccessor +Tjidde.Logging.Context.AsyncLocalCustomerContextAccessor.AsyncLocalCustomerContextAccessor() -> void +Tjidde.Logging.Context.AsyncLocalCustomerContextAccessor.GetCustomerContext() -> string? +Tjidde.Logging.Context.CustomerContext +Tjidde.Logging.Context.ICustomerContextAccessor +Tjidde.Logging.Context.ICustomerContextAccessor.GetCustomerContext() -> string? +Tjidde.Logging.Extensions.MethodScopeLoggerExtensions +Tjidde.Logging.Extensions.MetricsLoggerExtensions +Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions +Tjidde.Logging.Formatting.ExceptionFormatter +Tjidde.Logging.Formatting.ExceptionFormatter.ExceptionFormatter(bool includeStackTrace = true, bool includeInnerExceptions = true) -> void +Tjidde.Logging.Formatting.ExceptionFormatter.Format(System.Exception! exception) -> string! +Tjidde.Logging.Formatting.IExceptionFormatter +Tjidde.Logging.Formatting.IExceptionFormatter.Format(System.Exception! exception) -> string! +Tjidde.Logging.Logging.TjiddeLoggerProvider +Tjidde.Logging.Logging.TjiddeLoggerProvider.CreateLogger(string! categoryName) -> Microsoft.Extensions.Logging.ILogger! +Tjidde.Logging.Logging.TjiddeLoggerProvider.Dispose() -> void +Tjidde.Logging.Logging.TjiddeLoggerProvider.SetScopeProvider(Microsoft.Extensions.Logging.IExternalScopeProvider! scopeProvider) -> void +Tjidde.Logging.Logging.TjiddeLoggerProvider.TjiddeLoggerProvider(Microsoft.Extensions.Options.IOptionsMonitor! optionsMonitor, Tjidde.Logging.Context.ICustomerContextAccessor! customerContextAccessor, Tjidde.Logging.Masking.IMaskedKeysAccessor! maskedKeysAccessor) -> void +Tjidde.Logging.Masking.GlobalMaskedKeysAccessor +Tjidde.Logging.Masking.GlobalMaskedKeysAccessor.GetKeys() -> System.Collections.Generic.IReadOnlyCollection! +Tjidde.Logging.Masking.GlobalMaskedKeysAccessor.GlobalMaskedKeysAccessor() -> void +Tjidde.Logging.Masking.IMaskedKeysAccessor +Tjidde.Logging.Masking.IMaskedKeysAccessor.GetKeys() -> System.Collections.Generic.IReadOnlyCollection! +Tjidde.Logging.Masking.ISensitiveDataMasker +Tjidde.Logging.Masking.ISensitiveDataMasker.IsSensitiveKey(string! key) -> bool +Tjidde.Logging.Masking.ISensitiveDataMasker.MaskDictionary(System.Collections.Generic.IEnumerable>! properties) -> System.Collections.Generic.IReadOnlyDictionary! +Tjidde.Logging.Masking.ISensitiveDataMasker.MaskMessage(string! message) -> string! +Tjidde.Logging.Masking.ISensitiveDataMasker.MaskValue(string! key, string! value) -> string! +Tjidde.Logging.Masking.MaskedKeysContext +Tjidde.Logging.Masking.SensitiveDataMasker +Tjidde.Logging.Masking.SensitiveDataMasker.IsSensitiveKey(string! key) -> bool +Tjidde.Logging.Masking.SensitiveDataMasker.MaskDictionary(System.Collections.Generic.IEnumerable>! properties) -> System.Collections.Generic.IReadOnlyDictionary! +Tjidde.Logging.Masking.SensitiveDataMasker.MaskMessage(string! message) -> string! +Tjidde.Logging.Masking.SensitiveDataMasker.MaskValue(string! key, string! value) -> string! +Tjidde.Logging.Masking.SensitiveDataMasker.SensitiveDataMasker(string! placeholder = "[REDACTED]", System.Collections.Generic.IEnumerable? additionalKeys = null, System.Collections.Generic.IEnumerable? dynamicKeys = null) -> void +Tjidde.Logging.Options.TjiddeLoggerOptions +Tjidde.Logging.Options.TjiddeLoggerOptions.AdditionalSensitiveKeys.get -> System.Collections.Generic.IList! +Tjidde.Logging.Options.TjiddeLoggerOptions.AdditionalSensitiveKeys.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.CategoryMinimumLevels.get -> System.Collections.Generic.IDictionary! +Tjidde.Logging.Options.TjiddeLoggerOptions.CategoryMinimumLevels.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.EnableOpenTelemetryExport.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.EnableOpenTelemetryExport.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.EnableSensitiveDataMasking.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.EnableSensitiveDataMasking.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeInnerExceptions.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeInnerExceptions.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeScopes.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeScopes.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeStackTrace.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.IncludeStackTrace.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.MaskPlaceholder.get -> string! +Tjidde.Logging.Options.TjiddeLoggerOptions.MaskPlaceholder.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.MinimumLevel.get -> Microsoft.Extensions.Logging.LogLevel +Tjidde.Logging.Options.TjiddeLoggerOptions.MinimumLevel.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.OpenTelemetryActivitySourceName.get -> string! +Tjidde.Logging.Options.TjiddeLoggerOptions.OpenTelemetryActivitySourceName.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.OpenTelemetryCreateFallbackActivity.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.OpenTelemetryCreateFallbackActivity.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.OutputFormat.get -> Tjidde.Logging.Options.TjiddeLogOutputFormat +Tjidde.Logging.Options.TjiddeLoggerOptions.OutputFormat.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.ResolveMethodNameFromStackTrace.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.ResolveMethodNameFromStackTrace.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.TjiddeLoggerOptions() -> void +Tjidde.Logging.Options.TjiddeLogOutputFormat +Tjidde.Logging.Options.TjiddeLogOutputFormat.Json = 1 -> Tjidde.Logging.Options.TjiddeLogOutputFormat +Tjidde.Logging.Options.TjiddeLogOutputFormat.Text = 0 -> Tjidde.Logging.Options.TjiddeLogOutputFormat diff --git a/src/Tjidde.Logging/PublicAPI.Unshipped.txt b/src/Tjidde.Logging/PublicAPI.Unshipped.txt new file mode 100644 index 0000000..bf3ff81 --- /dev/null +++ b/src/Tjidde.Logging/PublicAPI.Unshipped.txt @@ -0,0 +1,59 @@ +#nullable enable +const Tjidde.Logging.Extensions.MetricsLoggerExtensions.MetricsEventIdValue = 10000 -> int +const Tjidde.Logging.Extensions.MetricsLoggerExtensions.MetricsEventName = "Metrics" -> string! +const Tjidde.Logging.Sinks.InMemoryLogSink.DefaultCapacity = 1000 -> int +override Tjidde.Logging.Sinks.TjiddeLogEntry.ToString() -> string! +static readonly Tjidde.Logging.Extensions.MetricsLoggerExtensions.MetricsEventId -> Microsoft.Extensions.Logging.EventId +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeInMemorySink(this Microsoft.Extensions.Logging.ILoggingBuilder! builder, int capacity = 1000) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeSink(this Microsoft.Extensions.Logging.ILoggingBuilder! builder) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.AddTjiddeSink(this Microsoft.Extensions.Logging.ILoggingBuilder! builder, TSink! sink) -> Microsoft.Extensions.Logging.ILoggingBuilder! +static Tjidde.Logging.Extensions.TjiddeLoggingBuilderExtensions.UseIsolatedMaskedKeys(this Microsoft.Extensions.Logging.ILoggingBuilder! builder) -> Microsoft.Extensions.Logging.ILoggingBuilder! +Tjidde.Logging.Logging.TjiddeLoggerProvider.TjiddeLoggerProvider(Microsoft.Extensions.Options.IOptionsMonitor! optionsMonitor, Tjidde.Logging.Context.ICustomerContextAccessor! customerContextAccessor, Tjidde.Logging.Masking.IMaskedKeysAccessor! maskedKeysAccessor, System.TimeProvider! timeProvider) -> void +Tjidde.Logging.Logging.TjiddeLoggerProvider.TjiddeLoggerProvider(Microsoft.Extensions.Options.IOptionsMonitor! optionsMonitor, Tjidde.Logging.Context.ICustomerContextAccessor! customerContextAccessor, Tjidde.Logging.Masking.IMaskedKeysAccessor! maskedKeysAccessor, System.TimeProvider! timeProvider, System.Collections.Generic.IEnumerable? sinks) -> void +Tjidde.Logging.Masking.MaskedKeysStore +Tjidde.Logging.Masking.MaskedKeysStore.Add(params string![]! keys) -> void +Tjidde.Logging.Masking.MaskedKeysStore.Clear() -> void +Tjidde.Logging.Masking.MaskedKeysStore.GetKeys() -> System.Collections.Generic.IReadOnlyCollection! +Tjidde.Logging.Masking.MaskedKeysStore.MaskedKeysStore() -> void +Tjidde.Logging.Masking.MaskedKeysStore.Remove(params string![]! keys) -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.UseUtcTimestamp.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.UseUtcTimestamp.set -> void +Tjidde.Logging.Options.TjiddeLoggerOptions.WriteToConsole.get -> bool +Tjidde.Logging.Options.TjiddeLoggerOptions.WriteToConsole.set -> void +Tjidde.Logging.Sinks.ILogSink +Tjidde.Logging.Sinks.ILogSink.Write(Tjidde.Logging.Sinks.TjiddeLogEntry! entry) -> void +Tjidde.Logging.Sinks.InMemoryLogSink +Tjidde.Logging.Sinks.InMemoryLogSink.Capacity.get -> int +Tjidde.Logging.Sinks.InMemoryLogSink.Clear() -> void +Tjidde.Logging.Sinks.InMemoryLogSink.Cleared -> System.EventHandler? +Tjidde.Logging.Sinks.InMemoryLogSink.Count.get -> int +Tjidde.Logging.Sinks.InMemoryLogSink.EntryAdded -> System.EventHandler? +Tjidde.Logging.Sinks.InMemoryLogSink.GetSnapshot() -> System.Collections.Generic.IReadOnlyList! +Tjidde.Logging.Sinks.InMemoryLogSink.InMemoryLogSink() -> void +Tjidde.Logging.Sinks.InMemoryLogSink.InMemoryLogSink(int capacity) -> void +Tjidde.Logging.Sinks.InMemoryLogSink.Write(Tjidde.Logging.Sinks.TjiddeLogEntry! entry) -> void +Tjidde.Logging.Sinks.TjiddeLogEntry +Tjidde.Logging.Sinks.TjiddeLogEntry.Category.get -> string! +Tjidde.Logging.Sinks.TjiddeLogEntry.Category.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.ClassName.get -> string! +Tjidde.Logging.Sinks.TjiddeLogEntry.ClassName.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.Customer.get -> string? +Tjidde.Logging.Sinks.TjiddeLogEntry.Customer.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.EventId.get -> Microsoft.Extensions.Logging.EventId +Tjidde.Logging.Sinks.TjiddeLogEntry.EventId.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.FormattedException.get -> string? +Tjidde.Logging.Sinks.TjiddeLogEntry.FormattedException.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.IsMetrics.get -> bool +Tjidde.Logging.Sinks.TjiddeLogEntry.Level.get -> Microsoft.Extensions.Logging.LogLevel +Tjidde.Logging.Sinks.TjiddeLogEntry.Level.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.Message.get -> string! +Tjidde.Logging.Sinks.TjiddeLogEntry.Message.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.MethodName.get -> string? +Tjidde.Logging.Sinks.TjiddeLogEntry.MethodName.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.OutputFormat.get -> Tjidde.Logging.Options.TjiddeLogOutputFormat +Tjidde.Logging.Sinks.TjiddeLogEntry.OutputFormat.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.RenderedLine.get -> string! +Tjidde.Logging.Sinks.TjiddeLogEntry.RenderedLine.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.Timestamp.get -> System.DateTimeOffset +Tjidde.Logging.Sinks.TjiddeLogEntry.Timestamp.init -> void +Tjidde.Logging.Sinks.TjiddeLogEntry.TjiddeLogEntry() -> void diff --git a/src/Tjidde.Logging/Sinks/ILogSink.cs b/src/Tjidde.Logging/Sinks/ILogSink.cs new file mode 100644 index 0000000..45fcef8 --- /dev/null +++ b/src/Tjidde.Logging/Sinks/ILogSink.cs @@ -0,0 +1,30 @@ +namespace Tjidde.Logging.Sinks; + +/// +/// A destination for Tjidde log entries besides (or instead of) the console, for example an in-memory buffer +/// for a UI, a file or a test assertion. Register sinks in DI (services.AddSingleton<ILogSink, MySink>()) +/// or with AddTjiddeSink; the provider passes every entry it writes to every sink. +/// +/// +/// +/// is called synchronously on the thread that logs, after the entry is rendered and masked. +/// Keep it fast and non-blocking: queue slow work (network, disk) yourself. +/// +/// +/// Implementations must be thread-safe: several threads can log at the same time. +/// An exception thrown by a sink is caught and ignored; it never reaches the caller and never stops other sinks +/// or the console from receiving the entry. Entries logged from inside are not passed to the +/// sinks again (they still go to the console), so a sink that logs cannot recurse. +/// +/// +/// Sinks are resolved when the logger provider is created, so a sink must not depend on ILogger<T> +/// or ILoggerFactory through its constructor (that is a circular dependency). The container disposes sinks +/// it created; the provider does not. +/// +/// +public interface ILogSink +{ + /// Receives one log entry. Called synchronously; must be fast and thread-safe. + /// The entry; contains only masked data. + void Write(TjiddeLogEntry entry); +} diff --git a/src/Tjidde.Logging/Sinks/InMemoryLogSink.cs b/src/Tjidde.Logging/Sinks/InMemoryLogSink.cs new file mode 100644 index 0000000..0bd3ca4 --- /dev/null +++ b/src/Tjidde.Logging/Sinks/InMemoryLogSink.cs @@ -0,0 +1,86 @@ +namespace Tjidde.Logging.Sinks; + +/// +/// A thread-safe that keeps the most recent entries in memory, for example to show them in a UI +/// or to assert on them in tests. When is reached, the oldest entry is dropped. +/// +/// +/// Register it with builder.AddTjiddeInMemorySink() and inject to read the entries. +/// +public sealed class InMemoryLogSink : ILogSink +{ + /// The capacity used by the parameterless constructor. + public const int DefaultCapacity = 1000; + + private readonly Queue _entries = new(); + private readonly object _lock = new(); + + /// Creates a sink that keeps at most entries. + public InMemoryLogSink() + : this(DefaultCapacity) + { + } + + /// Creates a sink that keeps at most entries. + /// is less than 1. + public InMemoryLogSink(int capacity) + { + if (capacity < 1) + throw new ArgumentOutOfRangeException(nameof(capacity), capacity, "The capacity must be at least 1."); + + Capacity = capacity; + } + + /// + /// Raised after an entry was added, on the thread that logged it. Keep handlers short and marshal to the UI + /// thread yourself. An exception from a handler does not reach the code that logged. + /// + public event EventHandler? EntryAdded; + + /// Raised after removed all entries, on the thread that called it. + public event EventHandler? Cleared; + + /// The maximum number of entries kept. + public int Capacity { get; } + + /// The number of entries currently kept. + public int Count + { + get + { + lock (_lock) + return _entries.Count; + } + } + + /// + public void Write(TjiddeLogEntry entry) + { + ArgumentNullException.ThrowIfNull(entry); + + lock (_lock) + { + _entries.Enqueue(entry); + while (_entries.Count > Capacity) + _entries.Dequeue(); + } + + EntryAdded?.Invoke(this, entry); + } + + /// Returns a copy of the kept entries, oldest first. Later writes do not change the returned list. + public IReadOnlyList GetSnapshot() + { + lock (_lock) + return _entries.ToArray(); + } + + /// Removes all kept entries and raises . + public void Clear() + { + lock (_lock) + _entries.Clear(); + + Cleared?.Invoke(this, EventArgs.Empty); + } +} diff --git a/src/Tjidde.Logging/Sinks/LogSinkDispatcher.cs b/src/Tjidde.Logging/Sinks/LogSinkDispatcher.cs new file mode 100644 index 0000000..88e5d3a --- /dev/null +++ b/src/Tjidde.Logging/Sinks/LogSinkDispatcher.cs @@ -0,0 +1,61 @@ +namespace Tjidde.Logging.Sinks; + +/// +/// Passes entries to the registered s, synchronously and in registration order. +/// A failing sink is ignored and does not affect the others. +/// +internal sealed class LogSinkDispatcher +{ + public static readonly LogSinkDispatcher Empty = new(null); + + // Set while this thread is inside a sink, so an entry logged by a sink is not dispatched again (no recursion). + [ThreadStatic] + private static bool _dispatching; + + private readonly ILogSink[] _sinks; + + public LogSinkDispatcher(IEnumerable? sinks) + { + var unique = new List(); + if (sinks is not null) + { + foreach (var sink in sinks) + { + // The same instance can be registered twice (e.g. AddTjiddeSink and AddSingleton); write to it once. + if (sink is not null && !unique.Exists(existing => ReferenceEquals(existing, sink))) + unique.Add(sink); + } + } + + _sinks = unique.ToArray(); + } + + /// Whether entries should be built for the sinks at all: there are sinks and this is not a nested call. + public bool IsActive => _sinks.Length > 0 && !_dispatching; + + public void Dispatch(TjiddeLogEntry entry) + { + if (!IsActive) + return; + + _dispatching = true; + try + { + foreach (var sink in _sinks) + { + try + { + sink.Write(entry); + } + catch (Exception) + { + // A sink must never break logging or keep the other sinks from receiving the entry. + } + } + } + finally + { + _dispatching = false; + } + } +} diff --git a/src/Tjidde.Logging/Sinks/TjiddeLogEntry.cs b/src/Tjidde.Logging/Sinks/TjiddeLogEntry.cs new file mode 100644 index 0000000..15ae173 --- /dev/null +++ b/src/Tjidde.Logging/Sinks/TjiddeLogEntry.cs @@ -0,0 +1,58 @@ +using Microsoft.Extensions.Logging; +using Tjidde.Logging.Extensions; +using Tjidde.Logging.Options; + +namespace Tjidde.Logging.Sinks; + +/// +/// One log entry as written by Tjidde.Logging, passed to every . Immutable. +/// +/// +/// Every text in the entry has gone through the same sensitive data masking as the console output +/// (when is on): the entry never contains +/// unmasked values. +/// +public sealed class TjiddeLogEntry +{ + /// When the entry was logged: UTC or local time, depending on . + public DateTimeOffset Timestamp { get; init; } + + /// The log level. Metrics entries have ; see . + public LogLevel Level { get; init; } + + /// The event ID of the entry: for LogMetrics entries. + public EventId EventId { get; init; } + + /// The logger category, usually the full type name. + public string Category { get; init; } = string.Empty; + + /// The last segment of , as shown after Class=>. + public string ClassName { get; init; } = string.Empty; + + /// The method name from a MethodName scope (or the stack trace, when enabled); otherwise . + public string? MethodName { get; init; } + + /// The customer from the customer context, or . + public string? Customer { get; init; } + + /// The rendered, masked message. + public string Message { get; init; } = string.Empty; + + /// The formatted, masked exception (type, message, stack trace, inner exceptions), or . + public string? FormattedException { get; init; } + + /// The complete line as Tjidde.Logging renders it for the console: text or JSON, depending on . + public string RenderedLine { get; init; } = string.Empty; + + /// The format of . + public TjiddeLogOutputFormat OutputFormat { get; init; } + + /// + /// Whether this is a metrics entry (written by LogMetrics: event name "Metrics"), + /// shown as [METRICS] in the console. + /// + public bool IsMetrics => MetricsLoggerExtensions.IsMetricsEntry(Level, EventId); + + /// Returns . + public override string ToString() => RenderedLine; +} diff --git a/src/Tjidde.Logging/Tjidde.Logging.csproj b/src/Tjidde.Logging/Tjidde.Logging.csproj index 8ae6348..bd0cc11 100644 --- a/src/Tjidde.Logging/Tjidde.Logging.csproj +++ b/src/Tjidde.Logging/Tjidde.Logging.csproj @@ -6,7 +6,8 @@ latest enable true - false + false + latest-recommended Tjidde.Logging @@ -26,6 +27,11 @@ false + + + true + 1.0.1 + + + + diff --git a/tests/Tjidde.Logging.Tests/LogSinkTests.cs b/tests/Tjidde.Logging.Tests/LogSinkTests.cs new file mode 100644 index 0000000..414c8c8 --- /dev/null +++ b/tests/Tjidde.Logging.Tests/LogSinkTests.cs @@ -0,0 +1,445 @@ +using System.Collections.Concurrent; +using System.Text.Json; +using FluentAssertions; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Tjidde.Logging.Context; +using Tjidde.Logging.Extensions; +using Tjidde.Logging.Logging; +using Tjidde.Logging.Masking; +using Tjidde.Logging.Options; +using Tjidde.Logging.Sinks; +using Xunit; + +namespace Tjidde.Logging.Tests; + +/// Extra s next to the console, and the built-in . +[Collection("ConsoleOutput")] +public sealed class LogSinkTests +{ + private static string CaptureConsoleOutput(Action action) + { + var original = Console.Out; + var writer = new StringWriter(); + Console.SetOut(writer); + try + { + action(); + } + finally + { + Console.SetOut(original); + } + return writer.ToString(); + } + + private static string[] Lines(string output) + => output.Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries); + + private static TjiddeLoggerProvider CreateProvider(TestOptionsMonitor monitor, params ILogSink[] sinks) + => new(monitor, new FixedCustomer("Acme"), new MaskedKeysStore(), TimeProvider.System, sinks); + + [Fact] + public void ExtraSink_ReceivesEntryWithMaskedValuesOnly() + { + var sink = new InMemoryLogSink(); + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions()); + + var output = CaptureConsoleOutput(() => + { + using var provider = CreateProvider(monitor, sink); + provider.SetScopeProvider(new LoggerExternalScopeProvider()); + var logger = provider.CreateLogger("My.App.LoginService"); + using (logger.BeginScope(new Dictionary { ["MethodName"] = "SignIn" })) + { + logger.LogWarning( + new EventId(42, "Login"), + new InvalidOperationException("failed with password=hunter2"), + "Login for {User} with {Password} and token=abc123", "alice", "s3cret!"); + } + }); + + var entry = sink.GetSnapshot().Should().ContainSingle().Subject; + entry.Level.Should().Be(LogLevel.Warning); + entry.EventId.Should().Be(new EventId(42, "Login")); + entry.Category.Should().Be("My.App.LoginService"); + entry.ClassName.Should().Be("LoginService"); + entry.MethodName.Should().Be("SignIn"); + entry.Customer.Should().Be("Acme"); + entry.OutputFormat.Should().Be(TjiddeLogOutputFormat.Text); + entry.IsMetrics.Should().BeFalse(); + entry.Timestamp.Should().BeCloseTo(DateTimeOffset.Now, TimeSpan.FromMinutes(1)); + + entry.Message.Should().Contain("alice").And.Contain("[REDACTED]"); + entry.FormattedException.Should().Contain("InvalidOperationException").And.Contain("[REDACTED]"); + foreach (var text in new[] { entry.Message, entry.FormattedException!, entry.RenderedLine }) + { + text.Should().NotContain("s3cret!"); + text.Should().NotContain("abc123"); + text.Should().NotContain("hunter2"); + } + + // The sink gets exactly the line the console gets. + Lines(output).Should().ContainSingle().Which.Should().Be(entry.RenderedLine); + } + + [Fact] + public void JsonFormat_RenderedLineIsJsonAndMessageIsMasked() + { + var sink = new InMemoryLogSink(); + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { OutputFormat = TjiddeLogOutputFormat.Json, WriteToConsole = false }); + + using (var provider = CreateProvider(monitor, sink)) + provider.CreateLogger("Json.Category").LogInformation("Connect with {Password}", "p@ss"); + + var entry = sink.GetSnapshot().Should().ContainSingle().Subject; + entry.OutputFormat.Should().Be(TjiddeLogOutputFormat.Json); + entry.Message.Should().NotContain("p@ss").And.Contain("[REDACTED]"); + entry.RenderedLine.Should().NotContain("p@ss"); + + using var json = JsonDocument.Parse(entry.RenderedLine); + json.RootElement.GetProperty("message").GetString().Should().Be(entry.Message); + } + + [Fact] + public void MetricsEntry_IsRecognizedByEventId() + { + var sink = new InMemoryLogSink(); + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { WriteToConsole = false }); + + using (var provider = CreateProvider(monitor, sink)) + provider.CreateLogger("Metrics.Category").LogMetrics("requests_total={Count}", 42); + + var entry = sink.GetSnapshot().Should().ContainSingle().Subject; + entry.IsMetrics.Should().BeTrue(); + entry.Level.Should().Be(LogLevel.Information); + entry.EventId.Should().Be(MetricsLoggerExtensions.MetricsEventId); + entry.RenderedLine.Should().Contain("[METRICS]"); + } + + [Fact] + public void WriteToConsoleFalse_WritesOnlyToSinks_AndReloadSwitchesTheConsoleBackOn() + { + var sink = new InMemoryLogSink(); + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { WriteToConsole = false }); + + var output = CaptureConsoleOutput(() => + { + using var provider = CreateProvider(monitor, sink); + var logger = provider.CreateLogger("Console.Switch"); + + logger.LogInformation("first, sink only"); + + monitor.Set(new TjiddeLoggerOptions { WriteToConsole = true }); + logger.LogInformation("second, console and sink"); + + monitor.Set(new TjiddeLoggerOptions { WriteToConsole = false }); + logger.LogInformation("third, sink only"); + }); + + Lines(output).Should().ContainSingle().Which.Should().EndWith("second, console and sink"); + sink.GetSnapshot().Select(e => e.Message) + .Should().Equal("first, sink only", "second, console and sink", "third, sink only"); + } + + [Fact] + public void WriteToConsole_IsBoundFromConfigurationAndReloads() + { + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(new Dictionary { ["TjiddeLogger:WriteToConsole"] = "false" }) + .Build(); + + InMemoryLogSink? sink = null; + var output = CaptureConsoleOutput(() => + { + var services = new ServiceCollection(); + services.AddLogging(builder => builder.AddTjiddeLogger(configuration).AddTjiddeInMemorySink()); + using var provider = services.BuildServiceProvider(); + sink = provider.GetRequiredService(); + var logger = provider.GetRequiredService>(); + + logger.LogInformation("hidden from console"); + configuration["TjiddeLogger:WriteToConsole"] = "true"; + configuration.Reload(); + logger.LogInformation("visible on console"); + }); + + Lines(output).Should().ContainSingle().Which.Should().EndWith("visible on console"); + sink!.Count.Should().Be(2); + } + + [Fact] + public void ThrowingSink_DoesNotBreakLogging_AndOtherSinksAndConsoleStillReceiveEntries() + { + var throwing = new ThrowingSink(); + var sink = new InMemoryLogSink(); + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions()); + + var output = CaptureConsoleOutput(() => + { + using var provider = CreateProvider(monitor, throwing, sink); + var logger = provider.CreateLogger("Throwing.Sink"); + + logger.Invoking(l => l.LogError("one")).Should().NotThrow(); + logger.Invoking(l => l.LogError("two")).Should().NotThrow(); + }); + + throwing.Calls.Should().Be(2); + sink.GetSnapshot().Select(e => e.Message).Should().Equal("one", "two"); + Lines(output).Should().HaveCount(2); + } + + [Fact] + public void SinkThatLogs_DoesNotRecurse() + { + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { WriteToConsole = false }); + var recursive = new RecursiveSink(); + var sink = new InMemoryLogSink(); + + using (var provider = CreateProvider(monitor, recursive, sink)) + { + recursive.Logger = provider.CreateLogger("Recursive.Sink"); + recursive.Logger.LogInformation("outer"); + } + + recursive.Calls.Should().Be(1); + sink.GetSnapshot().Select(e => e.Message).Should().Equal("outer"); + } + + [Theory] + [InlineData(TjiddeLogOutputFormat.Text)] + [InlineData(TjiddeLogOutputFormat.Json)] + public void EntryLoggedWhileReadingScopes_DoesNotAffectTheOuterEntry(TjiddeLogOutputFormat format) + { + // A scope value whose ToString() logs: the nested call runs while the outer entry is reading its scopes, + // on the same thread, and both entries must still get their own method name, scopes and line. + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { WriteToConsole = false, OutputFormat = format }); + var sink = new InMemoryLogSink(); + var value = new LoggingValue(); + + using (var provider = CreateProvider(monitor, sink)) + { + provider.SetScopeProvider(new LoggerExternalScopeProvider()); + var logger = provider.CreateLogger("My.App.OrderService"); + value.Logger = logger; + using (logger.BeginScope("Order pipeline")) + using (logger.BeginScope(new Dictionary { ["MethodName"] = "Process", ["Item"] = value })) + { + logger.LogInformation("outer {Count}", 1); + } + } + + var entries = sink.GetSnapshot(); + entries.Select(e => e.Message).Should().Equal("inner [REDACTED]", "outer 1"); + entries.Select(e => e.MethodName).Should().Equal("Process", "Process"); + if (format == TjiddeLogOutputFormat.Text) + { + entries[0].RenderedLine.Should().EndWith("inner [REDACTED] [Masked: Password] | Scopes: Order pipeline > Item=value"); + entries[1].RenderedLine.Should().EndWith("outer 1 | Scopes: Order pipeline > Item=value"); + } + else + { + foreach (var entry in entries) + { + using var json = JsonDocument.Parse(entry.RenderedLine); + json.RootElement.GetProperty("scopes").EnumerateArray().Select(e => e.GetString()) + .Should().Equal("Order pipeline", "Item=value"); + } + } + } + + private sealed class LoggingValue + { + private bool _logged; + public ILogger? Logger; + + public override string ToString() + { + if (!_logged) + { + _logged = true; + Logger?.LogInformation("inner {Password}", "hunter2"); + } + + return "value"; + } + } + + [Fact] + public void JsonFormat_WritesPropertyValuesLikeTheSerializer() + { + // Repeated names keep their first position and last value; strings are escaped by the default encoder; + // an unpaired surrogate becomes U+FFFD and NaN falls back to its text, as with JsonSerializer. + var monitor = new TestOptionsMonitor(new TjiddeLoggerOptions { WriteToConsole = false, OutputFormat = TjiddeLogOutputFormat.Json }); + var sink = new InMemoryLogSink(); + + using (var provider = CreateProvider(monitor, sink)) + { + provider.CreateLogger("My.App.OrderService").LogInformation( + "{A} {A} {B} {Emoji} {Lone} {Long} {Flag} {Dbl} {Nan} {Dec} {Missing}", + 1, 2, "x\"<>&\u00e9\n\t'+`", "\U0001F600 password=e", "a\ud800b", 5L, true, 1.5, double.NaN, 2.50m, null); + } + + sink.GetSnapshot().Single().RenderedLine.Should().EndWith( + "\"properties\":{\"A\":2,\"B\":\"x\\u0022\\u003C\\u003E\\u0026\\u00E9\\n\\t\\u0027\\u002B\\u0060\"," + + "\"Emoji\":\"\\uD83D\\uDE00 password=[REDACTED]\",\"Lone\":\"a\\uFFFDb\",\"Long\":5,\"Flag\":true," + + "\"Dbl\":1.5,\"Nan\":\"NaN\",\"Dec\":2.50,\"Missing\":null}}"); + } + + [Fact] + public void DependencyInjection_PassesEntriesToEveryRegisteredSink() + { + var instance = new InMemoryLogSink(10); + var services = new ServiceCollection(); + services.AddSingleton(); + services.AddLogging(builder => builder + .AddTjiddeLogger(o => o.WriteToConsole = false) + .AddTjiddeInMemorySink(capacity: 5) + .AddTjiddeInMemorySink() + .AddTjiddeSink() + .AddTjiddeSink() + .AddTjiddeSink(instance)); + + using var provider = services.BuildServiceProvider(); + var logger = provider.GetRequiredService>(); + logger.LogInformation("hello"); + + var inMemory = provider.GetRequiredService(); + inMemory.Capacity.Should().Be(5, "the first registration wins"); + inMemory.Count.Should().Be(1); + instance.Count.Should().Be(1); + provider.GetServices().OfType().Single().Calls.Should().Be(1); + provider.GetRequiredService().Calls.Should().Be(1, "registering the same sink type twice has no effect"); + } + + [Fact] + public void InMemoryLogSink_KeepsOnlyTheNewestEntriesUpToCapacity() + { + var sink = new InMemoryLogSink(3); + + for (var i = 0; i < 10; i++) + sink.Write(new TjiddeLogEntry { Message = $"m{i}" }); + + sink.Capacity.Should().Be(3); + sink.Count.Should().Be(3); + sink.GetSnapshot().Select(e => e.Message).Should().Equal("m7", "m8", "m9"); + } + + [Fact] + public void InMemoryLogSink_RejectsCapacityBelowOne() + { + FluentActions.Invoking(() => new InMemoryLogSink(0)).Should().Throw(); + new InMemoryLogSink().Capacity.Should().Be(InMemoryLogSink.DefaultCapacity); + } + + [Fact] + public void InMemoryLogSink_SnapshotIsACopy_AndEventsAreRaised() + { + var sink = new InMemoryLogSink(); + var added = new List(); + var cleared = 0; + sink.EntryAdded += (_, e) => added.Add(e); + sink.Cleared += (_, _) => cleared++; + + var entry = new TjiddeLogEntry { Message = "a" }; + sink.Write(entry); + var snapshot = sink.GetSnapshot(); + sink.Write(new TjiddeLogEntry { Message = "b" }); + + snapshot.Should().ContainSingle(); + added.Select(e => e.Message).Should().Equal("a", "b"); + added[0].Should().BeSameAs(entry); + + sink.Clear(); + sink.Count.Should().Be(0); + snapshot.Should().ContainSingle(); + cleared.Should().Be(1); + } + + [Fact] + public async Task InMemoryLogSink_IsThreadSafe() + { + const int threads = 8; + const int perThread = 2000; + var bounded = new InMemoryLogSink(500); + var unbounded = new InMemoryLogSink(threads * perThread); + var errors = new ConcurrentQueue(); + using var done = new CancellationTokenSource(); + + var reader = Task.Run(() => + { + while (!done.IsCancellationRequested) + { + try + { + bounded.GetSnapshot().Count.Should().BeLessThanOrEqualTo(500); + _ = unbounded.Count; + } + catch (Exception ex) + { + errors.Enqueue(ex); + } + } + }); + + Parallel.For(0, threads, new ParallelOptions { MaxDegreeOfParallelism = threads }, t => + { + for (var i = 0; i < perThread; i++) + { + var entry = new TjiddeLogEntry { Message = $"{t}:{i}" }; + bounded.Write(entry); + unbounded.Write(entry); + } + }); + + done.Cancel(); + await reader.WaitAsync(TimeSpan.FromSeconds(10)); + + errors.Should().BeEmpty(); + bounded.Count.Should().Be(500); + unbounded.GetSnapshot().Select(e => e.Message).Should().OnlyHaveUniqueItems().And.HaveCount(threads * perThread); + } + + private sealed class FixedCustomer(string customer) : ICustomerContextAccessor + { + public string? GetCustomerContext() => customer; + } + + private sealed class ThrowingSink : ILogSink + { + public int Calls; + + public void Write(TjiddeLogEntry entry) + { + Interlocked.Increment(ref Calls); + throw new InvalidOperationException("sink failure"); + } + } + + private sealed class RecursiveSink : ILogSink + { + public int Calls; + public ILogger? Logger; + + public void Write(TjiddeLogEntry entry) + { + Interlocked.Increment(ref Calls); + Logger?.LogInformation("logged from inside a sink"); + } + } + + private sealed class CountingSink : ILogSink + { + public int Calls; + + public void Write(TjiddeLogEntry entry) => Interlocked.Increment(ref Calls); + } + + private sealed class CountingSink2 : ILogSink + { + public int Calls; + + public void Write(TjiddeLogEntry entry) => Interlocked.Increment(ref Calls); + } +} diff --git a/tests/Tjidde.Logging.Tests/SensitiveDataMaskerTests.cs b/tests/Tjidde.Logging.Tests/SensitiveDataMaskerTests.cs index 489f978..8cc5b13 100644 --- a/tests/Tjidde.Logging.Tests/SensitiveDataMaskerTests.cs +++ b/tests/Tjidde.Logging.Tests/SensitiveDataMaskerTests.cs @@ -205,6 +205,38 @@ public void RuntimeKeys_ChangesApplyToAnExistingMasker() masker.IsSensitiveKey("SuperSecret42").Should().BeFalse(); } + [Theory] + [InlineData("Order processed successfully")] + [InlineData("Tokens of appreciation")] + [InlineData("caf\u00e9 au lait, no keys here")] + public void MaskMessage_LeavesTextWithoutSensitiveValuesUnchanged(string message) + { + _masker.MaskMessage(message).Should().Be(message); + } + + [Fact] + public void MaskMessage_MasksKeyWrittenWithNonAsciiCaseVariant() + { + // The Kelvin sign matches "k" case-insensitively, so the quick key check must not skip this text. + _masker.MaskMessage("to\u212Aen=abc123").Should().Be("to\u212Aen=[REDACTED]"); + } + + [Fact] + public void MaskMessage_MasksAsciiTextForNonAsciiKey() + { + var masker = new SensitiveDataMasker(additionalKeys: ["\u212Aeycode"]); + + masker.MaskMessage("keycode=abc123").Should().Be("keycode=[REDACTED]"); + } + + [Fact] + public void MaskMessage_MasksEveryKey_WhenPlaceholderIsNonAscii() + { + var masker = new SensitiveDataMasker(placeholder: "\u2588\u2588"); + + masker.MaskMessage("password=abc token=def").Should().Be("password=\u2588\u2588 token=\u2588\u2588"); + } + private sealed class FakeMaskedKeysAccessor : IMaskedKeysAccessor { public IReadOnlyCollection Keys { get; set; } = []; diff --git a/tests/Tjidde.Logging.Tests/SharedMaskerTests.cs b/tests/Tjidde.Logging.Tests/SharedMaskerTests.cs index 3da5aeb..6fc4b78 100644 --- a/tests/Tjidde.Logging.Tests/SharedMaskerTests.cs +++ b/tests/Tjidde.Logging.Tests/SharedMaskerTests.cs @@ -38,7 +38,7 @@ public void Loggers_ShareOneMaskerPerConfiguration_AndSwitchTogetherOnOptionsCha [Theory] [InlineData(true)] [InlineData(false)] - public void ConcurrentLogging_WhileMaskedKeysChange_KeepsMaskingAndNeverThrows(bool useGlobalContext) + public async Task ConcurrentLogging_WhileMaskedKeysChange_KeepsMaskingAndNeverThrows(bool useGlobalContext) { var id = Guid.NewGuid().ToString("N"); var permanentKey = $"perm-{id}"; @@ -88,16 +88,16 @@ public void ConcurrentLogging_WhileMaskedKeysChange_KeepsMaskingAndNeverThrows(b try { - Task.WaitAll(loggers); + await Task.WhenAll(loggers); } - catch (AggregateException ex) + catch { - errors.AddRange(ex.InnerExceptions); + errors.AddRange(loggers.Where(task => task.Exception is not null).SelectMany(task => task.Exception!.InnerExceptions)); } finally { stop.Cancel(); - churn.Wait(); + await churn; } } } diff --git a/tests/Tjidde.Logging.Tests/Tjidde.Logging.Tests.csproj b/tests/Tjidde.Logging.Tests/Tjidde.Logging.Tests.csproj index c45184c..5e8e655 100644 --- a/tests/Tjidde.Logging.Tests/Tjidde.Logging.Tests.csproj +++ b/tests/Tjidde.Logging.Tests/Tjidde.Logging.Tests.csproj @@ -12,7 +12,7 @@ - + + @@ -57,20 +57,20 @@ - - - - - + + + + + - - - - - + + + + +