From 4200a905fa6e5f826c052a0a430bc4824d0ad272 Mon Sep 17 00:00:00 2001 From: Aaron Stannard Date: Mon, 24 Nov 2025 17:01:28 -0600 Subject: [PATCH] feat: Add native semantic logging support with property extraction (#7933) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat: Add native semantic logging support to Akka.NET core Implements semantic/structured logging with support for both positional ({0}) and named ({PropertyName}) message templates, enabling structured property extraction for external logging frameworks. Key Features: - MessageTemplateParser with ThreadStatic LRU cache for template parsing - LogMessage enhanced with PropertyNames and GetProperties() APIs - SemanticLogMessageFormatter for Serilog-style template formatting - LogEventExtensions helper methods for easy property extraction - StandardOutLogger updated to display semantic properties - Zero new dependencies - pure BCL implementation - Full backward compatibility maintained Performance Optimizations: - ThreadStatic caching avoids lock contention - Lazy property evaluation (zero cost if not used) - FrozenDictionary on .NET 8+ for optimal read performance - LRU eviction prevents unbounded cache growth Testing: - 25 new unit tests covering template parsing, property extraction, and formatting - All 79 existing logger tests pass (full backward compatibility) - Tests validate positional templates, named templates, edge cases, and caching This enables external logger plugins (Serilog, NLog, MEL) to easily extract structured properties using logEvent.TryGetProperties() for integration with their native structured logging capabilities. Addresses #7932 * perf: optimize semantic logging memory allocations (75% reduction) Implemented Priority 1 performance optimizations to reduce GC pressure in semantic logging operations. Changes: - LogMessage.GetProperties(): Avoid ToArray() when Parameters() returns IReadOnlyList (LogValues structs), saving ~200-300 bytes - SemanticLogMessageFormatter.Format(): Check args type before conversion, use IReadOnlyList directly for named templates, only convert to array when required by string.Format(), saving ~500-800 bytes - SemanticLoggingBenchmarks: Add comprehensive benchmark suite (34 benchmarks) and fix GlobalSetup to include GetProperties benchmarks Performance Results: - Full E2E pipeline: 1592B → 400B (75% reduction) 🎯 - Format 3 params: 1248B → 680B (45% reduction) - GetProperties access: 526ns → 1.7ns (99.7% faster) - Template cache hits: 70ns → 47ns (33% faster) - E2E semantic logging: 1.34μs → 284ns (79% faster) All 79 unit tests passing. Benchmarks confirm optimizations maintain correctness while achieving target allocation reductions. Addresses #7932 * Enable SemanticLogMessageFormatter as default logger formatter Changed the default logger formatter from DefaultLogMessageFormatter to SemanticLogMessageFormatter to enable semantic logging support by default. This allows both positional {0} and named {PropertyName} templates to work out of the box. Changes: - Updated akka.conf to use SemanticLogMessageFormatter as default - Added special case handling in Settings.cs for SemanticLogMessageFormatter singleton instance All 62 existing logger tests pass, confirming backward compatibility with positional templates while enabling new semantic logging capabilities. * feat: Add EventFilter support for semantic logging templates Enables EventFilter to match against semantic logging templates in unit tests, resolving the core issue from GitHub #7932 where EventFilter.Info("BetId:{BetId}") would fail to match log messages using named property syntax. Changes: - Modified EventFilterBase.InternalDoMatch to check LogMessage.Format template before falling back to formatted output - Allows matching against both template patterns ("{UserId}") and formatted values ("12345") - Added comprehensive tests for EventFilter with semantic templates (exact match, contains, starts with) - Removed FormatException catching for positional templates to maintain backward compatibility with DefaultLogMessageFormatter All 66 logger tests pass, including 4 new EventFilter semantic logging tests and existing backward compatibility tests. * test: Add semantic logging integration tests for log filtering Added 8 comprehensive tests verifying that log filtering works correctly with semantic logging templates. Tests cover: - Filtering by formatted message content with named properties - Filtering by property values (e.g., {AlertLevel} = "CRITICAL") - Multiple properties in single log message - Positional templates with filtering (backward compatibility) - Source filtering combined with semantic logging - Format specifiers in templates (e.g., {Amount:N2}) - Messages that should pass through filters All 25 log filter tests pass (17 existing + 8 new), confirming semantic logging integrates seamlessly with the log filtering system introduced in v1.5.21. * fix: Update ConfigurationSpec to expect SemanticLogMessageFormatter as default Updated the configuration validation test to expect SemanticLogMessageFormatter instead of DefaultLogMessageFormatter as the default logger formatter, matching the change made in commit f9a2d2c16. All 4 configuration tests pass. * fix: enable nullable reference types in LogEventExtensions - Added #nullable enable directive - Marked 'properties' out parameter as nullable in TryGetProperties - Ensures proper null safety for the semantic logging API * test: Add semantic logging edge cases verification test - Added ShouldHandleSemanticLogEdgeCases test to DefaultLogFormatSpec - Tests named properties, positional properties, mixed types, null values, special characters, booleans, dates, and formatting alignment - Reuses existing sanitization methods from DefaultLogFormatSpec - Verifies semantic logging formatter output for various edge cases * Update API Approval list * Add new edge case unit tests (failing) * docs: Add Message Templates spec reference to SemanticLogMessageFormatter - Added link to https://messagetemplates.org/ specification - Documented supported syntax (named/positional properties, format specifiers, alignment, escaped braces) - Documented unsupported syntax (destructuring operators, empty property names) * fix: Correct escaped brace handling in semantic logging per Message Templates spec Parser fixes: - Removed incorrect }} check after placeholder closing brace - Parser now correctly extracts {UserId} from "{UserId}}" and "{{{UserId}}}" Formatter fixes: - Rewrote FormatNamedTemplate to handle }} in literal text correctly - Added UnescapeBraces helper for templates with no placeholders - "Use {{ and }}" now correctly produces "Use { and }" Test updates: - Updated {:N2} test to document as invalid per Message Templates spec - Invalid templates have "garbage in, garbage out" behavior (not crashing) Fixes edge cases reported in commit 1c58a6b4d. All 34 semantic logging tests now pass. * fix: Use culture-independent format specifiers in verify test The ShouldHandleSemanticLogEdgeCases verify test was failing on CI due to locale differences: - {Amount:C} produces $123.45 on US locale but ¤123.45 on invariant - DateTime.ToString() produces different formats per locale Changed to culture-independent formats: - Use ${Amount:F2} (literal $ + fixed-point number) instead of {Amount:C} - Use {JoinDate:yyyy-MM-dd} (ISO 8601) for dates * test: Add escaped brace benchmarks and .NET Framework verified file - Added benchmark category for escaped brace handling to track performance of edge case fixes - Added .Net.verified.txt baseline for .NET Framework 4.8 CI runs * Add unit tests * fix: Implement alignment specifiers and null ToString() handling in SemanticLogMessageFormatter - Add support for alignment specifiers in named templates per Message Templates spec - Parse {Name,alignment:format} syntax correctly - Apply PadLeft() for positive alignment (right-align) - Apply PadRight() for negative alignment (left-align) - Fix null handling when ToString() returns null - Check ToString() result before attempting format operations - Return "null" string instead of empty string for null ToString() results - Handles both plain and formatted property cases - Fix test bug: missing '>' character in alignment test format string These changes ensure the semantic logging formatter correctly implements the Message Templates specification for alignment and handles defensive edge cases. --------- Co-authored-by: Gregorius Soedharmo --- .../Logging/SemanticLoggingBenchmarks.cs | 534 ++++++++++++++++++ src/core/Akka.API.Tests/LogFormatSpec.cs | 80 ++- ...oreAPISpec.ApproveCore.DotNet.verified.txt | 19 + .../CoreAPISpec.ApproveCore.Net.verified.txt | 19 + ...leSemanticLogEdgeCases.DotNet.verified.txt | 11 + ...andleSemanticLogEdgeCases.Net.verified.txt | 11 + .../EventFilter/Internal/EventFilterBase.cs | 26 +- .../Configuration/ConfigurationSpec.cs | 2 +- .../Loggers/LogFilterEvaluatorSpecs.cs | 195 +++++++ .../Loggers/SemanticLoggingSpecs.cs | 495 ++++++++++++++++ src/core/Akka/Actor/Settings.cs | 5 + src/core/Akka/Configuration/akka.conf | 2 +- src/core/Akka/Event/LogEventExtensions.cs | 111 ++++ src/core/Akka/Event/LogMessage.cs | 111 ++++ src/core/Akka/Event/MessageTemplateParser.cs | 213 +++++++ .../Akka/Event/SemanticLogMessageFormatter.cs | 494 ++++++++++++++++ src/core/Akka/Event/StandardOutLogger.cs | 3 +- 17 files changed, 2317 insertions(+), 14 deletions(-) create mode 100644 src/benchmark/Akka.Benchmarks/Logging/SemanticLoggingBenchmarks.cs create mode 100644 src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.DotNet.verified.txt create mode 100644 src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.Net.verified.txt create mode 100644 src/core/Akka.Tests/Loggers/SemanticLoggingSpecs.cs create mode 100644 src/core/Akka/Event/LogEventExtensions.cs create mode 100644 src/core/Akka/Event/MessageTemplateParser.cs create mode 100644 src/core/Akka/Event/SemanticLogMessageFormatter.cs diff --git a/src/benchmark/Akka.Benchmarks/Logging/SemanticLoggingBenchmarks.cs b/src/benchmark/Akka.Benchmarks/Logging/SemanticLoggingBenchmarks.cs new file mode 100644 index 00000000000..614cd1b82be --- /dev/null +++ b/src/benchmark/Akka.Benchmarks/Logging/SemanticLoggingBenchmarks.cs @@ -0,0 +1,534 @@ +//----------------------------------------------------------------------- +// +// Copyright (C) 2009-2025 Lightbend Inc. +// Copyright (C) 2013-2025 .NET Foundation +// +//----------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Linq; +using Akka.Benchmarks.Configurations; +using Akka.Event; +using BenchmarkDotNet.Attributes; +using static Akka.Benchmarks.Configurations.BenchmarkCategories; + +namespace Akka.Benchmarks.Logging +{ + /// + /// Benchmarks for semantic logging implementation in Akka.NET. + /// Tests template parsing, property extraction, and message formatting performance. + /// + /// Performance Targets: + /// - Template cache hit: <100ns + /// - Template parse (uncached): <5μs + /// - Full format operation: <2μs + /// - Property extraction: <1μs (with caching) + /// - GC pressure: <200 bytes per log call + /// + [Config(typeof(MicroBenchmarkConfig))] + [MemoryDiagnoser] + public class SemanticLoggingBenchmarks + { + // ============================================================================ + // CATEGORY 1: Template Parsing - Cache Performance + // ============================================================================ + + private const string SimpleTemplate = "User {UserId} logged in"; + private const string ComplexTemplate = "Request {RequestId} from {IpAddress} at {Timestamp:yyyy-MM-dd} returned {StatusCode} in {Duration:N2}ms"; + private const string PositionalTemplate = "Value {0} and {1} and {2}"; + + private string[] _varyingTemplates; + private const int TemplateVariations = 100; + + [GlobalSetup] + public void Setup() + { + // Pre-generate varying templates to test cache effectiveness + _varyingTemplates = new string[TemplateVariations]; + for (int i = 0; i < TemplateVariations; i++) + { + _varyingTemplates[i] = $"User {{UserId}} performed action {{Action{i}}}"; + } + + // Warm up the cache with first template + MessageTemplateParser.GetPropertyNames(SimpleTemplate); + } + + [Benchmark(Description = "Template parse - COLD (first time)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList TemplateParse_Cold() + { + // This simulates a cold cache by using a unique template each time + // Note: In reality this will pollute the cache, but shows worst-case + var template = $"Unique template {{Prop{Guid.NewGuid()}}}"; + return MessageTemplateParser.GetPropertyNames(template); + } + + [Benchmark(Description = "Template parse - WARM (cached)", Baseline = true)] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList TemplateParse_Warm() + { + // Should hit ThreadStatic cache - target <100ns + return MessageTemplateParser.GetPropertyNames(SimpleTemplate); + } + + [Benchmark(Description = "Template parse - Complex template (cached)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList TemplateParse_ComplexCached() + { + return MessageTemplateParser.GetPropertyNames(ComplexTemplate); + } + + [Benchmark(Description = "Template parse - Positional {0} (cached)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList TemplateParse_PositionalCached() + { + return MessageTemplateParser.GetPropertyNames(PositionalTemplate); + } + + [Benchmark(Description = "Template parse - Cache thrashing (100 templates)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList TemplateParse_CacheThrashing() + { + // Tests LRU eviction by cycling through many templates + var result = default(IReadOnlyList); + for (int i = 0; i < TemplateVariations; i++) + { + result = MessageTemplateParser.GetPropertyNames(_varyingTemplates[i]); + } + return result; + } + + // ============================================================================ + // CATEGORY 2: Property Extraction - LogMessage Performance + // ============================================================================ + + private LogMessage _simpleLogMessage1Param; + private LogMessage _simpleLogMessage3Params; + private LogMessage _complexLogMessage5Params; + private LogMessage _positionalLogMessage; + + [GlobalSetup(Target = nameof(PropertyExtraction_1Param) + "," + + nameof(PropertyExtraction_3Params) + "," + + nameof(PropertyExtraction_5Params) + "," + + nameof(PropertyExtraction_Positional) + "," + + nameof(PropertyExtraction_Cached) + "," + + nameof(GetProperties_1Param) + "," + + nameof(GetProperties_3Params) + "," + + nameof(GetProperties_5Params) + "," + + nameof(GetProperties_Cached))] + public void SetupPropertyExtraction() + { + _simpleLogMessage1Param = new LogMessage>( + DefaultLogMessageFormatter.Instance, + "User {UserId} logged in", + new LogValues(12345) + ); + + _simpleLogMessage3Params = new LogMessage>( + DefaultLogMessageFormatter.Instance, + "User {UserId} from {IpAddress} at {Timestamp}", + new LogValues(12345, "192.168.1.1", DateTime.UtcNow) + ); + + _complexLogMessage5Params = new LogMessage>( + DefaultLogMessageFormatter.Instance, + ComplexTemplate, + new LogValues( + Guid.NewGuid(), "192.168.1.1", DateTime.UtcNow, 200, 123.45 + ) + ); + + _positionalLogMessage = new LogMessage>( + DefaultLogMessageFormatter.Instance, + "Value {0} and {1} and {2}", + new LogValues(42, "test", 3.14) + ); + } + + [Benchmark(Description = "PropertyNames - 1 param (lazy init)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList PropertyExtraction_1Param() + { + // Tests lazy initialization cost + var msg = new LogMessage>( + DefaultLogMessageFormatter.Instance, + SimpleTemplate, + new LogValues(12345) + ); + return msg.PropertyNames; + } + + [Benchmark(Description = "PropertyNames - 3 params (lazy init)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList PropertyExtraction_3Params() + { + var msg = new LogMessage>( + DefaultLogMessageFormatter.Instance, + "User {UserId} from {IpAddress} at {Timestamp}", + new LogValues(12345, "192.168.1.1", DateTime.UtcNow) + ); + return msg.PropertyNames; + } + + [Benchmark(Description = "PropertyNames - 5 params (lazy init)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList PropertyExtraction_5Params() + { + var msg = new LogMessage>( + DefaultLogMessageFormatter.Instance, + ComplexTemplate, + new LogValues( + Guid.NewGuid(), "192.168.1.1", DateTime.UtcNow, 200, 123.45 + ) + ); + return msg.PropertyNames; + } + + [Benchmark(Description = "PropertyNames - Positional")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList PropertyExtraction_Positional() + { + var msg = new LogMessage>( + DefaultLogMessageFormatter.Instance, + PositionalTemplate, + new LogValues(42, "test", 3.14) + ); + return msg.PropertyNames; + } + + [Benchmark(Description = "PropertyNames - Cached (2nd access)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList PropertyExtraction_Cached() + { + // Should be cached after first access - target ~10ns + return _simpleLogMessage1Param.PropertyNames; + } + + // ============================================================================ + // CATEGORY 3: GetProperties() - Dictionary Construction + // ============================================================================ + + [Benchmark(Description = "GetProperties - 1 param")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary GetProperties_1Param() + { + return _simpleLogMessage1Param.GetProperties(); + } + + [Benchmark(Description = "GetProperties - 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary GetProperties_3Params() + { + return _simpleLogMessage3Params.GetProperties(); + } + + [Benchmark(Description = "GetProperties - 5 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary GetProperties_5Params() + { + return _complexLogMessage5Params.GetProperties(); + } + + [Benchmark(Description = "GetProperties - Cached (2nd access)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary GetProperties_Cached() + { + // Should be cached - target ~5ns + return _simpleLogMessage1Param.GetProperties(); + } + + // ============================================================================ + // CATEGORY 4: Message Formatting - SemanticLogMessageFormatter vs Default + // ============================================================================ + + private object[] _args1 = new object[] { 12345 }; + private object[] _args3 = new object[] { 12345, "192.168.1.1", DateTime.UtcNow }; + private object[] _args5 = new object[] { Guid.NewGuid(), "192.168.1.1", DateTime.UtcNow, 200, 123.45 }; + + [Benchmark(Description = "Format - Semantic 1 param")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Semantic_1Param() + { + return SemanticLogMessageFormatter.Instance.Format(SimpleTemplate, _args1); + } + + [Benchmark(Description = "Format - Semantic 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Semantic_3Params() + { + return SemanticLogMessageFormatter.Instance.Format( + "User {UserId} from {IpAddress} at {Timestamp}", + _args3 + ); + } + + [Benchmark(Description = "Format - Semantic 5 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Semantic_5Params() + { + return SemanticLogMessageFormatter.Instance.Format(ComplexTemplate, _args5); + } + + [Benchmark(Description = "Format - Semantic with format spec {Value:N2}")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Semantic_WithFormatSpec() + { + return SemanticLogMessageFormatter.Instance.Format( + "Duration was {Duration:N2}ms", + new object[] { 123.456789 } + ); + } + + [Benchmark(Description = "Format - Default (positional) 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Default_3Params() + { + return DefaultLogMessageFormatter.Instance.Format( + "Value {0} and {1} and {2}", + _args3 + ); + } + + [Benchmark(Description = "Format - Semantic Positional 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_Semantic_Positional_3Params() + { + return SemanticLogMessageFormatter.Instance.Format(PositionalTemplate, _args3); + } + + // ============================================================================ + // CATEGORY 5: End-to-End Logging Pipeline + // ============================================================================ + + private sealed class BenchmarkLogAdapter : LoggingAdapterBase + { + public LogEvent LastLog { get; private set; } + private readonly string _logSource; + private readonly Type _logClass; + + public BenchmarkLogAdapter(ILogMessageFormatter formatter) : base(formatter) + { + _logSource = LogSource.Create(this).Source; + _logClass = typeof(BenchmarkLogAdapter); + } + + public override bool IsDebugEnabled => true; + public override bool IsInfoEnabled => true; + public override bool IsWarningEnabled => true; + public override bool IsErrorEnabled => true; + + protected override void NotifyLog(LogLevel logLevel, object message, Exception cause = null) + { + LastLog = new Info(cause, _logSource, _logClass, message); + } + } + + private BenchmarkLogAdapter _defaultLogger; + private BenchmarkLogAdapter _semanticLogger; + + [GlobalSetup(Target = nameof(EndToEnd_Default_NoParams) + "," + + nameof(EndToEnd_Default_1Param) + "," + + nameof(EndToEnd_Default_3Params) + "," + + nameof(EndToEnd_Semantic_NoParams) + "," + + nameof(EndToEnd_Semantic_1Param) + "," + + nameof(EndToEnd_Semantic_3Params) + "," + + nameof(EndToEnd_Semantic_WithProperties))] + public void SetupEndToEnd() + { + _defaultLogger = new BenchmarkLogAdapter(DefaultLogMessageFormatter.Instance); + _semanticLogger = new BenchmarkLogAdapter(SemanticLogMessageFormatter.Instance); + } + + [Benchmark(Description = "E2E - Default formatter, no params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Default_NoParams() + { + _defaultLogger.Info("User logged in"); + return _defaultLogger.LastLog; + } + + [Benchmark(Description = "E2E - Default formatter, 1 param")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Default_1Param() + { + _defaultLogger.Info("User {0} logged in", 12345); + return _defaultLogger.LastLog; + } + + [Benchmark(Description = "E2E - Default formatter, 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Default_3Params() + { + _defaultLogger.Info("User {0} from {1} at {2}", 12345, "192.168.1.1", DateTime.UtcNow); + return _defaultLogger.LastLog; + } + + [Benchmark(Description = "E2E - Semantic formatter, no params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Semantic_NoParams() + { + _semanticLogger.Info("User logged in"); + return _semanticLogger.LastLog; + } + + [Benchmark(Description = "E2E - Semantic formatter, 1 param")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Semantic_1Param() + { + _semanticLogger.Info("User {UserId} logged in", 12345); + return _semanticLogger.LastLog; + } + + [Benchmark(Description = "E2E - Semantic formatter, 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public LogEvent EndToEnd_Semantic_3Params() + { + _semanticLogger.Info("User {UserId} from {IpAddress} at {Timestamp}", + 12345, "192.168.1.1", DateTime.UtcNow); + return _semanticLogger.LastLog; + } + + [Benchmark(Description = "E2E - Semantic with GetProperties()")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary EndToEnd_Semantic_WithProperties() + { + _semanticLogger.Info("User {UserId} from {IpAddress}", 12345, "192.168.1.1"); + var logEvent = _semanticLogger.LastLog; + if (logEvent.TryGetProperties(out var props)) + return props; + return null; + } + + // ============================================================================ + // CATEGORY 6: Allocation Benchmarks - Memory Pressure Analysis + // ============================================================================ + + [Benchmark(Description = "Allocations - Parse template (cold)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyList Allocations_ParseCold() + { + // Unique template to avoid cache + var template = $"Event {{Id}} at {{Time}} with {{Data}}"; + return MessageTemplateParser.GetPropertyNames(template); + } + + [Benchmark(Description = "Allocations - Format semantic 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Allocations_FormatSemantic() + { + return SemanticLogMessageFormatter.Instance.Format( + "User {UserId} from {IpAddress} at {Timestamp}", + new object[] { 12345, "192.168.1.1", DateTime.UtcNow } + ); + } + + [Benchmark(Description = "Allocations - GetProperties 3 params")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary Allocations_GetProperties() + { + var msg = new LogMessage>( + DefaultLogMessageFormatter.Instance, + "User {UserId} from {IpAddress} at {Timestamp}", + new LogValues(12345, "192.168.1.1", DateTime.UtcNow) + ); + return msg.GetProperties(); + } + + [Benchmark(Description = "Allocations - Full log + properties")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public IReadOnlyDictionary Allocations_FullPipeline() + { + _semanticLogger.Info("User {UserId} from {IpAddress} performed {Action}", + 12345, "192.168.1.1", "login"); + if (_semanticLogger.LastLog.TryGetProperties(out var props)) + return props; + return null; + } + + // ============================================================================ + // CATEGORY 7: Escaped Brace Handling + // ============================================================================ + + private const string EscapedBracesOnly = "Use {{ and }} for literals"; + private const string EscapedBracesWithPlaceholder = "{First}}} text {{more {Second}"; + private const string NestedEscapedBraces = "{{{UserId}}}"; + private const string TrailingEscapedBrace = "{UserId}}"; + + [Benchmark(Description = "Format - Escaped braces only (no placeholders)")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_EscapedBracesOnly() + { + // Tests UnescapeBraces path - no placeholders, just {{ and }} + return SemanticLogMessageFormatter.Instance.Format(EscapedBracesOnly, Array.Empty()); + } + + [Benchmark(Description = "Format - Escaped braces with placeholders")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_EscapedBracesWithPlaceholders() + { + // Tests FormatNamedTemplate with mixed escaped braces and placeholders + return SemanticLogMessageFormatter.Instance.Format( + EscapedBracesWithPlaceholder, + new object[] { 1, 2 } + ); + } + + [Benchmark(Description = "Format - Nested escaped braces {{{Value}}}")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_NestedEscapedBraces() + { + // Tests {{{ }}} pattern: escaped brace + placeholder + escaped brace + return SemanticLogMessageFormatter.Instance.Format(NestedEscapedBraces, new object[] { 123 }); + } + + [Benchmark(Description = "Format - Trailing escaped brace {Value}}")] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public string Format_TrailingEscapedBrace() + { + // Tests placeholder followed by literal } + return SemanticLogMessageFormatter.Instance.Format(TrailingEscapedBrace, new object[] { 123 }); + } + + // ============================================================================ + // CATEGORY 8: Stress Tests - Real-world Patterns + // ============================================================================ + + private const int BatchSize = 1000; + + [Benchmark(Description = "Stress - 1K logs (same template)", OperationsPerInvoke = BatchSize)] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public void Stress_1K_SameTemplate() + { + for (int i = 0; i < BatchSize; i++) + { + _semanticLogger.Info("User {UserId} logged in", i); + } + } + + [Benchmark(Description = "Stress - 1K logs (varying templates)", OperationsPerInvoke = BatchSize)] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public void Stress_1K_VaryingTemplates() + { + for (int i = 0; i < BatchSize; i++) + { + _semanticLogger.Info(_varyingTemplates[i % TemplateVariations], i); + } + } + + [Benchmark(Description = "Stress - 1K logs with property extraction", OperationsPerInvoke = BatchSize)] + [BenchmarkCategory(MicroBenchmark, AkkaEventBenchmark)] + public int Stress_1K_WithPropertyExtraction() + { + int propCount = 0; + for (int i = 0; i < BatchSize; i++) + { + _semanticLogger.Info("User {UserId} performed {Action}", i, $"Action{i}"); + if (_semanticLogger.LastLog.TryGetProperties(out var props)) + propCount += props.Count; + } + return propCount; + } + } +} diff --git a/src/core/Akka.API.Tests/LogFormatSpec.cs b/src/core/Akka.API.Tests/LogFormatSpec.cs index 5775ffcbc1e..bda336d43ef 100644 --- a/src/core/Akka.API.Tests/LogFormatSpec.cs +++ b/src/core/Akka.API.Tests/LogFormatSpec.cs @@ -32,9 +32,9 @@ public DefaultLogFormatSpec() : base(CustomLoggerSetup()) { _logger = (CustomLogger)Sys.Settings.StdoutLogger; } - + private readonly CustomLogger _logger; - + public class CustomLogger : StandardOutLogger { protected override void Log(object message) @@ -44,13 +44,13 @@ protected override void Log(object message) { _events.Add(e); } - + } - + private readonly ConcurrentBag _events = new(); public IReadOnlyCollection Events => _events; } - + public static ActorSystemSetup CustomLoggerSetup() { var hocon = @$" @@ -109,10 +109,76 @@ await AwaitConditionAsync(() => text = SanitizeThreadNumber(text); // to resolve https://github.com/akkadotnet/akka.net/issues/7421 text = SanitizeTestEventListener(text); - + await Verifier.Verify(text); } - + + [Fact] + public async Task ShouldHandleSemanticLogEdgeCases() + { + // arrange + var filePath = Path.GetTempFileName(); + + // act + using (new OutputRedirector(filePath)) + { + // Named properties + Sys.Log.Debug("User {UserId} logged in from {IpAddress}", 12345, "192.168.1.1"); + Sys.Log.Info("Processing order {OrderId} for customer {CustomerId}", "ORD-001", "CUST-999"); + + // Positional properties (old style) + Sys.Log.Warning("Processing item {0} of {1}", 5, 10); + + // Mixed types - use F2 instead of C for culture-independent output + Sys.Log.Info("Order total is ${Amount:F2} with {ItemCount} items", 123.45m, 3); + + // Edge cases + Sys.Log.Debug("Empty template"); + Sys.Log.Info("Single property {Value}", 42); + Sys.Log.Warning("Null value: {NullValue}", null); + Sys.Log.Error("Exception occurred for user {UserId}", 999); + + // Special characters and escaping + Sys.Log.Debug("Path: {FilePath}, Size: {FileSize} bytes", @"C:\temp\file.txt", 1024); + + // Boolean and date types - use explicit date format for culture-independent output + Sys.Log.Info("User {Username} is active: {IsActive}, joined on {JoinDate:yyyy-MM-dd}", "john.doe", true, DateTime.Parse("2024-01-15")); + + // Long strings and alignment + Sys.Log.Debug("Request from {RemoteAddress} to endpoint {Endpoint} took {DurationMs}ms", "192.168.1.100:54321", "/api/v1/users", 250); + + // force all logs to be received - wait for the last log message + await AwaitConditionAsync(() => Task.FromResult(_logger.Events.Any(e => e.Message.ToString()!.Contains("took 250ms"))), TimeSpan.FromSeconds(5)); + } + + // assert + // ReSharper disable once MethodHasAsyncOverload + var text = File.ReadAllText(filePath); + + // need to sanitize the thread id and timestamps + text = SanitizeDateTime(text); + text = SanitizeThreadNumber(text); + text = SanitizeTestEventListener(text); + text = SanitizeDefaultLoggersStarted(text); + text = SanitizeCustomLoggerRemoved(text); + + await Verifier.Verify(text); + } + + private static string SanitizeDefaultLoggersStarted(string logs) + { + var pattern = @"^.*Default Loggers started.*$\r?\n?"; + var result = Regex.Replace(logs, pattern, string.Empty, RegexOptions.Multiline); + return result; + } + + private static string SanitizeCustomLoggerRemoved(string logs) + { + var pattern = @"^.*CustomLogger being removed.*$\r?\n?"; + var result = Regex.Replace(logs, pattern, string.Empty, RegexOptions.Multiline); + return result; + } + private static string SanitizeTestEventListener(string logs) { var pattern = @"^.*Akka\.TestKit\.TestEventListener.*$"; diff --git a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt index 84f53c066a1..0e36be385d2 100644 --- a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt +++ b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt @@ -3483,6 +3483,17 @@ namespace Akka.Event public abstract Akka.Event.LogLevel LogLevel(); public override string ToString() { } } + [System.Runtime.CompilerServices.NullableAttribute(0)] + public class static LogEventExtensions + { + public static System.Collections.Generic.IEnumerable GetParameters(this Akka.Event.LogEvent evt) { } + public static System.Collections.Generic.IReadOnlyList GetPropertyNames(this Akka.Event.LogEvent evt) { } + public static string GetTemplate(this Akka.Event.LogEvent evt) { } + public static bool TryGetProperties(this Akka.Event.LogEvent evt, [System.Runtime.CompilerServices.NullableAttribute(new byte[] { + 2, + 1, + 1})] out System.Collections.Generic.IReadOnlyDictionary properties) { } + } public abstract class LogFilterBase : Akka.Actor.INoSerializationVerificationNeeded, Akka.Event.IDeadLetterSuppression { protected LogFilterBase() { } @@ -3542,6 +3553,8 @@ namespace Akka.Event protected readonly Akka.Event.ILogMessageFormatter Formatter; public LogMessage(Akka.Event.ILogMessageFormatter formatter, string format) { } public string Format { get; } + public System.Collections.Generic.IReadOnlyList PropertyNames { get; } + public System.Collections.Generic.IReadOnlyDictionary GetProperties() { } [Akka.Annotations.InternalApiAttribute()] public abstract System.Collections.Generic.IEnumerable Parameters(); [Akka.Annotations.InternalApiAttribute()] @@ -3719,6 +3732,12 @@ namespace Akka.Event public override Akka.Event.LogFilterType FilterType { get; } public override Akka.Event.LogFilterDecision ShouldKeepMessage(Akka.Event.LogEvent content, [System.Runtime.CompilerServices.NullableAttribute(2)] string expandedMessage = null) { } } + public sealed class SemanticLogMessageFormatter : Akka.Event.ILogMessageFormatter + { + public static readonly Akka.Event.SemanticLogMessageFormatter Instance; + public string Format(string format, params object[] args) { } + public string Format(string format, System.Collections.Generic.IEnumerable args) { } + } public class StandardOutLogger : Akka.Event.MinimalLogger { public StandardOutLogger() { } diff --git a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt index 6a23954802c..69fcd307543 100644 --- a/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt +++ b/src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt @@ -3474,6 +3474,17 @@ namespace Akka.Event public abstract Akka.Event.LogLevel LogLevel(); public override string ToString() { } } + [System.Runtime.CompilerServices.NullableAttribute(0)] + public class static LogEventExtensions + { + public static System.Collections.Generic.IEnumerable GetParameters(this Akka.Event.LogEvent evt) { } + public static System.Collections.Generic.IReadOnlyList GetPropertyNames(this Akka.Event.LogEvent evt) { } + public static string GetTemplate(this Akka.Event.LogEvent evt) { } + public static bool TryGetProperties(this Akka.Event.LogEvent evt, [System.Runtime.CompilerServices.NullableAttribute(new byte[] { + 2, + 1, + 1})] out System.Collections.Generic.IReadOnlyDictionary properties) { } + } public abstract class LogFilterBase : Akka.Actor.INoSerializationVerificationNeeded, Akka.Event.IDeadLetterSuppression { protected LogFilterBase() { } @@ -3533,6 +3544,8 @@ namespace Akka.Event protected readonly Akka.Event.ILogMessageFormatter Formatter; public LogMessage(Akka.Event.ILogMessageFormatter formatter, string format) { } public string Format { get; } + public System.Collections.Generic.IReadOnlyList PropertyNames { get; } + public System.Collections.Generic.IReadOnlyDictionary GetProperties() { } [Akka.Annotations.InternalApiAttribute()] public abstract System.Collections.Generic.IEnumerable Parameters(); [Akka.Annotations.InternalApiAttribute()] @@ -3708,6 +3721,12 @@ namespace Akka.Event public override Akka.Event.LogFilterType FilterType { get; } public override Akka.Event.LogFilterDecision ShouldKeepMessage(Akka.Event.LogEvent content, [System.Runtime.CompilerServices.NullableAttribute(2)] string expandedMessage = null) { } } + public sealed class SemanticLogMessageFormatter : Akka.Event.ILogMessageFormatter + { + public static readonly Akka.Event.SemanticLogMessageFormatter Instance; + public string Format(string format, params object[] args) { } + public string Format(string format, System.Collections.Generic.IEnumerable args) { } + } public class StandardOutLogger : Akka.Event.MinimalLogger { public StandardOutLogger() { } diff --git a/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.DotNet.verified.txt b/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.DotNet.verified.txt new file mode 100644 index 00000000000..e2c9fd90769 --- /dev/null +++ b/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.DotNet.verified.txt @@ -0,0 +1,11 @@ +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] User 12345 logged in from 192.168.1.1 +[INFO][DateTime][Thread 0001][ActorSystem(test)] Processing order ORD-001 for customer CUST-999 +[WARNING][DateTime][Thread 0001][ActorSystem(test)] Processing item 5 of 10 +[INFO][DateTime][Thread 0001][ActorSystem(test)] Order total is $123.45 with 3 items +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Empty template +[INFO][DateTime][Thread 0001][ActorSystem(test)] Single property 42 +[WARNING][DateTime][Thread 0001][ActorSystem(test)] Null value: {NullValue} +[ERROR][DateTime][Thread 0001][ActorSystem(test)] Exception occurred for user 999 +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Path: C:\temp\file.txt, Size: 1024 bytes +[INFO][DateTime][Thread 0001][ActorSystem(test)] User john.doe is active: True, joined on 2024-01-15 +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Request from 192.168.1.100:54321 to endpoint /api/v1/users took 250ms diff --git a/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.Net.verified.txt b/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.Net.verified.txt new file mode 100644 index 00000000000..e2c9fd90769 --- /dev/null +++ b/src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldHandleSemanticLogEdgeCases.Net.verified.txt @@ -0,0 +1,11 @@ +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] User 12345 logged in from 192.168.1.1 +[INFO][DateTime][Thread 0001][ActorSystem(test)] Processing order ORD-001 for customer CUST-999 +[WARNING][DateTime][Thread 0001][ActorSystem(test)] Processing item 5 of 10 +[INFO][DateTime][Thread 0001][ActorSystem(test)] Order total is $123.45 with 3 items +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Empty template +[INFO][DateTime][Thread 0001][ActorSystem(test)] Single property 42 +[WARNING][DateTime][Thread 0001][ActorSystem(test)] Null value: {NullValue} +[ERROR][DateTime][Thread 0001][ActorSystem(test)] Exception occurred for user 999 +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Path: C:\temp\file.txt, Size: 1024 bytes +[INFO][DateTime][Thread 0001][ActorSystem(test)] User john.doe is active: True, joined on 2024-01-15 +[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Request from 192.168.1.100:54321 to endpoint /api/v1/users took 250ms diff --git a/src/core/Akka.TestKit/EventFilter/Internal/EventFilterBase.cs b/src/core/Akka.TestKit/EventFilter/Internal/EventFilterBase.cs index 80ff0790281..69c9d9c9fd3 100644 --- a/src/core/Akka.TestKit/EventFilter/Internal/EventFilterBase.cs +++ b/src/core/Akka.TestKit/EventFilter/Internal/EventFilterBase.cs @@ -18,9 +18,9 @@ namespace Akka.TestKit.Internal /// TBD public delegate void EventMatched(EventFilterBase eventFilter, LogEvent logEvent); - /// Internal! + /// Internal! /// Facilities for selectively filtering out expected events from logging so - /// that you can keep your test run’s console output clean and do not miss real + /// that you can keep your test run's console output clean and do not miss real /// error messages. /// Note! Part of internal API. Breaking changes may occur without notice. Use at own risk. /// @@ -86,8 +86,26 @@ protected virtual void OnEventMatched(LogEvent logEvent) /// TBD protected bool InternalDoMatch(string src, object msg) { - var msgstr = msg == null ? "null" : msg.ToString(); - return _sourceMatcher.IsMatch(src) && _messageMatcher.IsMatch(msgstr); + // Check source matcher first (fast path) + if (!_sourceMatcher.IsMatch(src)) + return false; + + // For semantic logging support, try matching against both the formatted message + // and the unformatted template pattern + if (msg is LogMessage logMessage) + { + // Try matching against the template pattern first (e.g., "User {UserId} logged in") + if (_messageMatcher.IsMatch(logMessage.Format)) + return true; + + // Fall back to matching the formatted message (e.g., "User 12345 logged in") + var formattedMsg = logMessage.ToString() ?? "null"; + return _messageMatcher.IsMatch(formattedMsg); + } + + // Non-semantic logging or legacy messages + var msgstr = msg == null ? "null" : msg.ToString() ?? "null"; + return _messageMatcher.IsMatch(msgstr); } /// diff --git a/src/core/Akka.Tests/Configuration/ConfigurationSpec.cs b/src/core/Akka.Tests/Configuration/ConfigurationSpec.cs index 6241c7dfb41..6c204fcfa30 100644 --- a/src/core/Akka.Tests/Configuration/ConfigurationSpec.cs +++ b/src/core/Akka.Tests/Configuration/ConfigurationSpec.cs @@ -50,7 +50,7 @@ public void The_default_configuration_file_contain_all_configuration_properties( settings.LogDeadLetters.ShouldBe(10); settings.LogDeadLettersDuringShutdown.ShouldBeFalse(); settings.LogDeadLettersSuspendDuration.ShouldBe(TimeSpan.FromMinutes(5)); - settings.LogFormatter.Should().BeOfType(); + settings.LogFormatter.Should().BeOfType(); settings.ProviderClass.ShouldBe(typeof (LocalActorRefProvider).FullName); settings.SupervisorStrategyClass.ShouldBe(typeof (DefaultSupervisorStrategy).FullName); diff --git a/src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs b/src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs index 1ce5487109d..c75bdb88cdb 100644 --- a/src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs +++ b/src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs @@ -227,4 +227,199 @@ public void ShouldFilterByLogMessageContains(LogEvent e, bool expected) Assert.Equal(expected, keepMessage); } } + + /// + /// Tests that log filtering works correctly with semantic logging templates + /// + public class SemanticLoggingFilterCases + { + private static ILoggingAdapter CreateAdapter() + { + var system = ActorSystem.Create("test-system"); + return Logging.GetLogger(system, "TestLogger"); + } + + [Fact] + public void ShouldFilterSemanticLogByFormattedMessageContent() + { + // Arrange: filter should exclude messages containing "12345" + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("12345"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + var adapter = CreateAdapter(); + + // Act: log with semantic template - the formatted value contains "12345" + adapter.Info("User {UserId} logged in", 12345); + + // Get the LogEvent that was created + var logEvent = new Info( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "User {UserId} logged in", + 12345)); + + // Assert: should be filtered out because formatted message contains "12345" + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + + [Fact] + public void ShouldKeepSemanticLogWhenFormattedMessageDoesNotMatchFilter() + { + // Arrange: filter excludes messages containing "admin" + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("admin"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: log message where neither template nor formatted value contains "admin" + var logEvent = new Info( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "User {UserId} logged in from {IpAddress}", + 123, "192.168.1.1")); + + // Assert: should NOT be filtered (kept) + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.True(keepMessage); + } + + [Fact] + public void ShouldFilterSemanticLogByPropertyValue() + { + // Arrange: filter excludes messages containing "CRITICAL" + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("CRITICAL"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: the property value contains "CRITICAL" + var logEvent = new Warning( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Alert level {AlertLevel} triggered", + "CRITICAL")); + + // Assert: should be filtered because formatted message is "Alert level CRITICAL triggered" + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + + [Fact] + public void ShouldFilterSemanticLogWithMultipleProperties() + { + // Arrange: filter excludes messages containing "ERROR" + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("ERROR"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: multiple properties, one contains "ERROR" + var logEvent = new Error( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Status: {Status}, Code: {ErrorCode}, User: {UserId}", + "ERROR", 500, 789)); + + // Assert: should be filtered + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + + [Fact] + public void ShouldHandlePositionalTemplatesWithFiltering() + { + // Arrange: filter excludes "timeout" + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("timeout"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: positional template (backward compatibility) + var logEvent = new Warning( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Operation {0} failed with {1}", + "database query", "timeout")); + + // Assert: should be filtered because formatted contains "timeout" + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + + [Fact] + public void ShouldFilterBySourceWithSemanticLogging() + { + // Arrange: filter excludes source starting with "Akka.Tests" + var ruleBuilder = new LogFilterBuilder().ExcludeSourceStartingWith("Akka.Tests"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: semantic log from filtered source + var logEvent = new Info( + null, + "Akka.Tests.MyTest", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Test user {UserId} created", + 999)); + + // Assert: should be filtered by source (message content irrelevant) + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + + [Fact] + public void ShouldKeepSemanticLogWhenSourceAndMessagePass() + { + // Arrange: filter excludes "ERROR" in message and "Akka.Tests" in source + var ruleBuilder = new LogFilterBuilder() + .ExcludeMessageContaining("ERROR") + .ExcludeSourceContaining("Akka.Tests"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: semantic log that doesn't match either filter + var logEvent = new Info( + null, + "Akka.Cluster.Gossip", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Node {NodeAddress} joined cluster", + "akka.tcp://system@localhost:8080")); + + // Assert: should NOT be filtered (kept) + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.True(keepMessage); + } + + [Fact] + public void ShouldFilterComplexSemanticLogWithFormatSpecifiers() + { + // Arrange: filter excludes messages containing "1,234.56" (formatted number) + var ruleBuilder = new LogFilterBuilder().ExcludeMessageContaining("1,234.56"); + var evaluator = ruleBuilder.Build().CreateEvaluator(); + + // Act: semantic template with format specifier + var logEvent = new Info( + null, + "TestLogger", + typeof(SemanticLoggingFilterCases), + new DefaultLogMessage( + SemanticLogMessageFormatter.Instance, + "Amount {Amount:N2} processed", + 1234.56m)); + + // Assert: should be filtered because formatted output contains "1,234.56" + var keepMessage = evaluator.ShouldTryKeepMessage(logEvent, out _); + Assert.False(keepMessage); + } + } } diff --git a/src/core/Akka.Tests/Loggers/SemanticLoggingSpecs.cs b/src/core/Akka.Tests/Loggers/SemanticLoggingSpecs.cs new file mode 100644 index 00000000000..a7f2b4e19a8 --- /dev/null +++ b/src/core/Akka.Tests/Loggers/SemanticLoggingSpecs.cs @@ -0,0 +1,495 @@ +//----------------------------------------------------------------------- +// +// Copyright (C) 2009-2025 Lightbend Inc. +// Copyright (C) 2013-2025 .NET Foundation +// +//----------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Linq; +using Akka.Configuration; +using Akka.Event; +using Akka.TestKit; +using FluentAssertions; +using Xunit; + +namespace Akka.Tests.Loggers +{ + public class SemanticLoggingSpecs : AkkaSpec + { + public SemanticLoggingSpecs() : base(ConfigurationFactory.ParseString(@" + akka { + loglevel = INFO + stdout-loglevel = INFO + } + ")) + { + } + [Fact(DisplayName = "MessageTemplateParser should parse positional templates correctly")] + public void MessageTemplateParser_should_parse_positional_templates() + { + var template = "Value is {0} and status {1}"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(2); + propertyNames[0].Should().Be("0"); + propertyNames[1].Should().Be("1"); + } + + [Fact(DisplayName = "MessageTemplateParser should parse named templates correctly")] + public void MessageTemplateParser_should_parse_named_templates() + { + var template = "User {UserId} logged in from {IpAddress}"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(2); + propertyNames[0].Should().Be("UserId"); + propertyNames[1].Should().Be("IpAddress"); + } + + [Fact(DisplayName = "MessageTemplateParser should handle escaped braces")] + public void MessageTemplateParser_should_handle_escaped_braces() + { + var template = "Use {{braces}} for {Value}"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(1); + propertyNames[0].Should().Be("Value"); + } + + [Fact(DisplayName = "MessageTemplateParser should handle format specifiers")] + public void MessageTemplateParser_should_handle_format_specifiers() + { + var template = "Value is {Amount:N2} dollars"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(1); + propertyNames[0].Should().Be("Amount"); + } + + [Fact(DisplayName = "MessageTemplateParser should handle alignment specifiers")] + public void MessageTemplateParser_should_handle_alignment_specifiers() + { + var template = "Name: {Name,10} Age: {Age,-5}"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(2); + propertyNames[0].Should().Be("Name"); + propertyNames[1].Should().Be("Age"); + } + + [Fact(DisplayName = "MessageTemplateParser should return empty list for no placeholders")] + public void MessageTemplateParser_should_return_empty_for_no_placeholders() + { + var template = "This is a plain message"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + propertyNames.Should().NotBeNull(); + propertyNames.Should().BeEmpty(); + } + + [Fact(DisplayName = "MessageTemplateParser should handle malformed templates gracefully")] + public void MessageTemplateParser_should_handle_malformed_templates() + { + var template = "Value is {0 and {1} without closing"; + var propertyNames = MessageTemplateParser.GetPropertyNames(template); + + // Should not throw, parses "0 and {1" from the first {..} pair + propertyNames.Should().NotBeNull(); + propertyNames.Should().HaveCount(1); + propertyNames[0].Should().Be("0 and {1"); + } + + [Fact(DisplayName = "MessageTemplateParser should cache parsed templates")] + public void MessageTemplateParser_should_cache_parsed_templates() + { + var template = "User {UserId} logged in"; + + // First call - cache miss + var result1 = MessageTemplateParser.GetPropertyNames(template); + + // Second call - should hit cache (same reference) + var result2 = MessageTemplateParser.GetPropertyNames(template); + + result1.Should().BeSameAs(result2, "cached results should return the same instance"); + } + + [Fact(DisplayName = "LogMessage should extract property names correctly")] + public void LogMessage_should_extract_property_names() + { + var formatter = DefaultLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId} logged in", 123); + + var propertyNames = logMessage.PropertyNames; + + propertyNames.Should().HaveCount(1); + propertyNames[0].Should().Be("UserId"); + } + + [Fact(DisplayName = "LogMessage should create property dictionary correctly")] + public void LogMessage_should_create_property_dictionary() + { + var formatter = DefaultLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId} from {IpAddress}", 123, "192.168.1.1"); + + var properties = logMessage.GetProperties(); + + properties.Should().HaveCount(2); + properties["UserId"].Should().Be(123); + properties["IpAddress"].Should().Be("192.168.1.1"); + } + + [Fact(DisplayName = "LogMessage should handle mismatched property counts")] + public void LogMessage_should_handle_mismatched_property_counts() + { + var formatter = DefaultLogMessageFormatter.Instance; + + // More values than properties + var logMessage1 = new DefaultLogMessage(formatter, "User {UserId}", 123, "extra"); + var properties1 = logMessage1.GetProperties(); + properties1.Should().HaveCount(1); + properties1["UserId"].Should().Be(123); + + // More properties than values + var logMessage2 = new DefaultLogMessage(formatter, "User {UserId} from {IpAddress}"); + var properties2 = logMessage2.GetProperties(); + properties2.Should().BeEmpty(); + } + + [Fact(DisplayName = "LogMessage property dictionary should be cached")] + public void LogMessage_property_dictionary_should_be_cached() + { + var formatter = DefaultLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId}", 123); + + var properties1 = logMessage.GetProperties(); + var properties2 = logMessage.GetProperties(); + + properties1.Should().BeSameAs(properties2, "cached properties should return the same instance"); + } + + [Fact(DisplayName = "SemanticLogMessageFormatter should format positional templates")] + public void SemanticLogMessageFormatter_should_format_positional_templates() + { + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("Value is {0} and status {1}", 42, "OK"); + + result.Should().Be("Value is 42 and status OK"); + } + + [Fact(DisplayName = "SemanticLogMessageFormatter should format named templates")] + public void SemanticLogMessageFormatter_should_format_named_templates() + { + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("User {UserId} logged in from {IpAddress}", 123, "192.168.1.1"); + + result.Should().Be("User 123 logged in from 192.168.1.1"); + } + + [Fact(DisplayName = "SemanticLogMessageFormatter should handle format specifiers")] + public void SemanticLogMessageFormatter_should_handle_format_specifiers() + { + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("Amount: {Amount:N2}", 1234.5); + + // Handle culture differences - just check it contains the number with decimals + result.Should().MatchRegex(@"Amount: \d[,\d]*\.50"); + } + + [Fact(DisplayName = "SemanticLogMessageFormatter should handle missing arguments")] + public void SemanticLogMessageFormatter_should_handle_missing_arguments() + { + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("User {UserId} from {IpAddress}", 123); + + result.Should().Contain("123"); + result.Should().Contain("{IpAddress}"); // Missing arg stays as placeholder + } + + [Fact(DisplayName = "SemanticLogMessageFormatter should handle null values")] + public void SemanticLogMessageFormatter_should_handle_null_values() + { + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("Value is {Value}", (object)null); + + result.Should().Be("Value is null"); + } + + [Fact(DisplayName = "LogEventExtensions.TryGetProperties should work with LogMessage")] + public void LogEventExtensions_TryGetProperties_should_work_with_LogMessage() + { + var formatter = SemanticLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId}", 123); + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), logMessage); + + var result = logEvent.TryGetProperties(out var properties); + + result.Should().BeTrue(); + properties.Should().NotBeNull(); + properties["UserId"].Should().Be(123); + } + + [Fact(DisplayName = "LogEventExtensions.TryGetProperties should return false for string messages")] + public void LogEventExtensions_TryGetProperties_should_return_false_for_strings() + { + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), "Plain string message"); + + var result = logEvent.TryGetProperties(out var properties); + + result.Should().BeFalse(); + properties.Should().BeNull(); + } + + [Fact(DisplayName = "LogEventExtensions.GetPropertyNames should work with LogMessage")] + public void LogEventExtensions_GetPropertyNames_should_work() + { + var formatter = SemanticLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId} from {IpAddress}", 123, "192.168.1.1"); + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), logMessage); + + var propertyNames = logEvent.GetPropertyNames(); + + propertyNames.Should().HaveCount(2); + propertyNames.Should().Contain("UserId"); + propertyNames.Should().Contain("IpAddress"); + } + + [Fact(DisplayName = "LogEventExtensions.GetTemplate should extract format string")] + public void LogEventExtensions_GetTemplate_should_work() + { + var formatter = SemanticLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId}", 123); + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), logMessage); + + var template = logEvent.GetTemplate(); + + template.Should().Be("User {UserId}"); + } + + [Fact(DisplayName = "LogEventExtensions.GetParameters should extract values")] + public void LogEventExtensions_GetParameters_should_work() + { + var formatter = SemanticLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId} from {IpAddress}", 123, "192.168.1.1"); + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), logMessage); + + var parameters = logEvent.GetParameters().ToArray(); + + parameters.Should().HaveCount(2); + parameters[0].Should().Be(123); + parameters[1].Should().Be("192.168.1.1"); + } + + [Fact(DisplayName = "LruCache should evict oldest entries when full")] + public void LruCache_should_evict_oldest_entries() + { + var cache = new LruCache(3); + + cache.Add(1, "one"); + cache.Add(2, "two"); + cache.Add(3, "three"); + cache.Add(4, "four"); // Should evict 1 + + cache.TryGet(1, out _).Should().BeFalse("1 should have been evicted"); + cache.TryGet(2, out var val2).Should().BeTrue(); + val2.Should().Be("two"); + } + + [Fact(DisplayName = "LruCache should promote accessed entries")] + public void LruCache_should_promote_accessed_entries() + { + var cache = new LruCache(3); + + cache.Add(1, "one"); + cache.Add(2, "two"); + cache.Add(3, "three"); + + // Access 1, promoting it to front + cache.TryGet(1, out _).Should().BeTrue(); + + // Add 4, should evict 2 (oldest) + cache.Add(4, "four"); + + cache.TryGet(1, out _).Should().BeTrue("1 was promoted"); + cache.TryGet(2, out _).Should().BeFalse("2 should have been evicted"); + cache.TryGet(3, out _).Should().BeTrue(); + cache.TryGet(4, out _).Should().BeTrue(); + } + + [Fact(DisplayName = "End-to-end semantic logging should work")] + public void End_to_end_semantic_logging_should_work() + { + var formatter = SemanticLogMessageFormatter.Instance; + var logMessage = new DefaultLogMessage(formatter, "User {UserId} performed action {Action}", 123, "Login"); + var logEvent = new Info(null, "TestSource", typeof(SemanticLoggingSpecs), logMessage); + + // Property extraction + logEvent.TryGetProperties(out var properties).Should().BeTrue(); + properties["UserId"].Should().Be(123); + properties["Action"].Should().Be("Login"); + + // Template extraction + logEvent.GetTemplate().Should().Be("User {UserId} performed action {Action}"); + + // Message formatting + logMessage.ToString().Should().Be("User 123 performed action Login"); + } + + [Fact(DisplayName = "EventFilter should match semantic logging templates with named properties")] + public void EventFilter_should_match_semantic_templates() + { + // This test demonstrates the issue from GitHub #7932 + // EventFilter should match against the template pattern, not just the formatted output + + EventFilter.Info("OnCreateBet BetId:{BetId} created").ExpectOne(() => + { + Log.Info("OnCreateBet BetId:{BetId} created", 12345); + }); + } + + [Fact(DisplayName = "EventFilter should match semantic logging templates with contains")] + public void EventFilter_should_match_semantic_templates_with_contains() + { + EventFilter.Info(contains: "BetId:{BetId}").ExpectOne(() => + { + Log.Info("OnCreateBet BetId:{BetId} created", 12345); + }); + } + + [Fact(DisplayName = "EventFilter should match semantic logging templates with partial pattern")] + public void EventFilter_should_match_semantic_partial_pattern() + { + EventFilter.Info(start: "User {UserId}").ExpectOne(() => + { + Log.Info("User {UserId} logged in from {IpAddress}", 123, "192.168.1.1"); + }); + } + + [Fact(DisplayName = "EventFilter should still match formatted output when template doesn't match")] + public void EventFilter_should_fallback_to_formatted_output() + { + // Should also be able to match against the actual formatted values + EventFilter.Info(contains: "12345").ExpectOne(() => + { + Log.Info("OnCreateBet BetId:{BetId} created", 12345); + }); + } + + // BUG: Placeholder followed by }} fails + [Fact(DisplayName = "SemanticLogMessageFormatter should format '{UserId}}' with [123] to '123}'")] + public void Placeholder_followed_by_escaped_closing_brace_fails() + { + // CRITICAL: Parser treats }}} as "escaped brace", ignoring placeholder content + var propertyNames = MessageTemplateParser.GetPropertyNames("{UserId}}"); + propertyNames.Should().HaveCount(1, "parser must extract UserId"); + propertyNames[0].Should().Be("UserId"); + + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("{UserId}}", 123); + result.Should().Be("123}", "} closes placeholder, }} becomes }"); + } + + // BUG: Literal escaped braces not unescaped + [Fact(DisplayName = "SemanticLogMessageFormatter should format 'Use {{ and }}' to 'Use { and }'")] + public void Literal_escaped_braces_not_unescaped() + { + // CRITICAL: Templates without placeholders return raw string, no unescape + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("Use {{ and }} braces"); + result.Should().Be("Use { and } braces", "{{ → {, }} → }"); + } + + // BUG: Escaped braces around placeholders not unescaped + [Fact(DisplayName = "SemanticLogMessageFormatter should format '{First}}} text {{more {Second}' with [1, 2] to '1} text {more 2'")] + public void Escaped_braces_around_placeholders_not_unescaped() + { + // CRITICAL: Literal text between/after placeholders not processed for escaped braces + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("{First}}} text {{more {Second}", 1, 2); + result.Should().Be("1} text {more 2", "should unescape }} and {{ in literal text"); + } + + // BUG: Complex template {{{UserId}}} fails + [Fact(DisplayName = "SemanticLogMessageFormatter should format '{{{UserId}}}' with [123] to '{123}'")] + public void Complex_mixed_escaped_braces_and_placeholder_fails() + { + // CRITICAL: Combination of escaped braces + placeholder fails completely + var propertyNames = MessageTemplateParser.GetPropertyNames("{{{UserId}}}"); + propertyNames.Should().HaveCount(1, "must extract UserId"); + + var formatter = SemanticLogMessageFormatter.Instance; + var result = formatter.Format("{{{UserId}}}", 123); + result.Should().Be("{123}", "{{ → {, {UserId} → 123, }} → }"); + } + + // INVALID TEMPLATE: Empty property name with format specifier is not valid per Message Templates spec + // See: https://messagetemplates.org/ + // Property names must be valid identifiers - a format specifier alone ({:N2}) is malformed + [Fact(DisplayName = "Empty property name with format specifier {:N2} is invalid per spec")] + public void Empty_property_name_with_format_specifier_is_invalid() + { + // Per Message Templates spec, property names must be valid identifiers. + // {:N2} has no property name, only a format specifier - this is invalid. + // Current behavior: parser returns ":N2" as the property name (treating it as malformed but not crashing) + // This is acceptable "garbage in, garbage out" behavior for invalid templates. + var propertyNames = MessageTemplateParser.GetPropertyNames("{:N2}"); + + // We document but don't "fix" this - invalid templates have undefined behavior + propertyNames.Should().HaveCount(1, "parser extracts content even from invalid templates"); + // The colon is included because colonIndex > 0 check doesn't handle colon at position 0 + // This is intentional - we don't want to add complexity to handle invalid templates + } + + // BUG: Alignment specifiers ignored + [Fact(DisplayName = "SemanticLogMessageFormatter should format {Value,10:N2} with width and format")] + public void Alignment_specifiers_completely_ignored_in_named_templates() + { + // Per Message Templates spec, alignment IS supported: {PropertyName,Alignment:Format} + // Current code strips alignment but never applies it + var formatter = SemanticLogMessageFormatter.Instance; + + // Test 1: Simple alignment + var result1 = formatter.Format(">{Value,10}<", 123); + result1.Should().Be("> 123<", "positive alignment = right-align to 10 chars"); + + // Test 2: Negative alignment (left-align) + var result2 = formatter.Format(">{Value,-10}<", 123); + result2.Should().Be(">123 <", "negative alignment = left-align to 10 chars"); + + // Test 3: Combined alignment + format specifier + var result3 = formatter.Format("{Value,10:N2}", 123.456); + result3.Should().HaveLength(10, "alignment width must be applied"); + result3.Should().MatchRegex(@"^\s+\d{3}[.,]\d{2}$", "should be right-aligned with 2 decimals"); + } + + // BUG: ToString() returning null causes silent data loss + [Fact(DisplayName = "SemanticLogMessageFormatter should format ToString() returning null correctly")] + public void ToString_returning_null_should_be_handled() + { + // If type's ToString() returns null (violates .NET guidelines but possible), + // value silently disappears instead of showing "null" + var formatter = SemanticLogMessageFormatter.Instance; + var badObject = new TypeWithNullToString(); + + // Without format specifier - exercises line 258 + var result1 = formatter.Format("{Value}", badObject); + result1.Should().Be("null", "ToString() null should be treated as explicit null"); + + // With format specifier - exercises catch block line 253 + var result2 = formatter.Format("{Value:N2}", badObject); + result2.Should().Be("null", "ToString() null in catch block should be handled"); + } + + // Helper class for testing ToString() returning null + private class TypeWithNullToString + { + public override string ToString() => null; + } + } +} diff --git a/src/core/Akka/Actor/Settings.cs b/src/core/Akka/Actor/Settings.cs index 120663f5dae..3b180ba62be 100644 --- a/src/core/Akka/Actor/Settings.cs +++ b/src/core/Akka/Actor/Settings.cs @@ -182,6 +182,11 @@ public Settings(ActorSystem system, Config config, ActorSystemSetup setup) { LogFormatter = DefaultLogMessageFormatter.Instance; } + // SPECIAL CASE - check for the semantic log message formatter, which does not have an empty constructor (it's private) + else if (logFormatType == typeof(SemanticLogMessageFormatter)) + { + LogFormatter = SemanticLogMessageFormatter.Instance; + } else { try diff --git a/src/core/Akka/Configuration/akka.conf b/src/core/Akka/Configuration/akka.conf index df5704d8f94..86bb15706a9 100644 --- a/src/core/Akka/Configuration/akka.conf +++ b/src/core/Akka/Configuration/akka.conf @@ -32,7 +32,7 @@ akka { # Specifies the formatter used to format log messages. Can be customized # to use a different logging implementation, such as Serilog. - logger-formatter = "Akka.Event.DefaultLogMessageFormatter, Akka" + logger-formatter = "Akka.Event.SemanticLogMessageFormatter, Akka" # Log level used by the configured loggers (see "loggers") as soon # as they have been started; before that, see "stdout-loglevel" diff --git a/src/core/Akka/Event/LogEventExtensions.cs b/src/core/Akka/Event/LogEventExtensions.cs new file mode 100644 index 00000000000..9d8d5685070 --- /dev/null +++ b/src/core/Akka/Event/LogEventExtensions.cs @@ -0,0 +1,111 @@ +//----------------------------------------------------------------------- +// +// Copyright (C) 2009-2025 Lightbend Inc. +// Copyright (C) 2013-2025 .NET Foundation +// +//----------------------------------------------------------------------- + +#nullable enable + +using System; +using System.Collections.Generic; +using System.Linq; + +namespace Akka.Event +{ + /// + /// Extension methods for accessing semantic logging properties from instances. + /// These methods make it easy for custom logger implementations to extract structured properties. + /// + public static class LogEventExtensions + { + /// + /// Attempts to extract structured properties from the log event message. + /// + /// The log event + /// The extracted properties dictionary (if successful) + /// True if properties were extracted, false if message is a pre-formatted string + /// + /// + /// if (logEvent.TryGetProperties(out var properties)) + /// { + /// // Use structured properties with your native logger + /// foreach (var prop in properties) + /// { + /// Console.WriteLine($"{prop.Key} = {prop.Value}"); + /// } + /// } + /// + /// + public static bool TryGetProperties( + this LogEvent evt, + out IReadOnlyDictionary? properties) + { + if (evt.Message is LogMessage msg) + { + properties = msg.GetProperties(); + return true; + } + + properties = null; + return false; + } + + /// + /// Gets the property names from the log event's message template. + /// Returns empty list if message is a pre-formatted string. + /// + /// The log event + /// List of property names, or empty list + /// + /// + /// var names = logEvent.GetPropertyNames(); + /// // For "User {UserId} logged in", returns ["UserId"] + /// + /// + public static IReadOnlyList GetPropertyNames(this LogEvent evt) + { + return evt.Message is LogMessage msg + ? msg.PropertyNames + : Array.Empty(); + } + + /// + /// Gets the message template format string from the log event. + /// + /// The log event + /// Template string if LogMessage, otherwise the string representation + /// + /// + /// var template = logEvent.GetTemplate(); + /// // For semantic logs, returns "User {UserId} logged in" + /// // For pre-formatted strings, returns the actual message + /// + /// + public static string GetTemplate(this LogEvent evt) + { + return evt.Message is LogMessage msg + ? msg.Format + : evt.Message?.ToString() ?? string.Empty; + } + + /// + /// Gets the parameter values from the log message. + /// Returns empty enumerable if message is a pre-formatted string. + /// + /// The log event + /// Parameter values, or empty enumerable + /// + /// + /// var parameters = logEvent.GetParameters().ToArray(); + /// // For log.Info("User {0}", 123), returns [123] + /// + /// + public static IEnumerable GetParameters(this LogEvent evt) + { + return evt.Message is LogMessage msg + ? msg.Parameters() + : Enumerable.Empty(); + } + } +} diff --git a/src/core/Akka/Event/LogMessage.cs b/src/core/Akka/Event/LogMessage.cs index 955541dfe52..64eb3634c36 100644 --- a/src/core/Akka/Event/LogMessage.cs +++ b/src/core/Akka/Event/LogMessage.cs @@ -25,16 +25,35 @@ public static class LogMessageExtensions{ /// /// /// Call ToString to get the formatted output. + /// Supports semantic logging by extracting property names from message templates. /// public abstract class LogMessage { protected readonly ILogMessageFormatter Formatter; + private IReadOnlyList? _propertyNames; + private IReadOnlyDictionary? _properties; /// /// Gets the format string of this log message. /// public string Format { get; private set; } + /// + /// Gets the property names extracted from the message template. + /// For positional templates like "{0} and {1}", returns ["0", "1"]. + /// For named templates like "{UserId} logged in", returns ["UserId"]. + /// This property uses lazy initialization and caching for performance. + /// + public IReadOnlyList PropertyNames + { + get + { + if (_propertyNames == null) + _propertyNames = MessageTemplateParser.GetPropertyNames(Format); + return _propertyNames; + } + } + /// /// Initializes an instance of the LogMessage with the specified formatter, format and args. /// @@ -46,6 +65,98 @@ public LogMessage(ILogMessageFormatter formatter, string format) Format = format; } + /// + /// Gets a dictionary of property names to their values. + /// Combines PropertyNames with Parameters() to create name-value pairs. + /// This method uses lazy initialization and caching for performance. + /// + /// A read-only dictionary of property names and values + public IReadOnlyDictionary GetProperties() + { + if (_properties == null) + { + var names = PropertyNames; + var parameters = Parameters(); + + // Optimize: avoid ToArray() if Parameters() already returns IReadOnlyList + if (parameters is IReadOnlyList readOnlyList) + { + _properties = CreatePropertyDictionary(names, readOnlyList); + } + else if (parameters is object[] array) + { + _properties = CreatePropertyDictionary(names, array); + } + else + { + // Fallback: convert to array + _properties = CreatePropertyDictionary(names, parameters.ToArray()); + } + } + return _properties; + } + + private static IReadOnlyDictionary CreatePropertyDictionary( + IReadOnlyList names, + IReadOnlyList values) + { + // Handle empty case + if (names.Count == 0) + return EmptyDictionary; + + // Handle mismatched counts (more values than names, or vice versa) + var count = Math.Min(names.Count, values.Count); + if (count == 0) + return EmptyDictionary; + + var dict = new Dictionary(count); + for (int i = 0; i < count; i++) + { + dict[names[i]] = values[i]; + } + +#if NET8_0_OR_GREATER + // Use FrozenDictionary for optimal read performance on .NET 8+ + return System.Collections.Frozen.FrozenDictionary.ToFrozenDictionary(dict); +#else + return dict; +#endif + } + + private static IReadOnlyDictionary CreatePropertyDictionary( + IReadOnlyList names, + object[] values) + { + // Handle empty case + if (names.Count == 0) + return EmptyDictionary; + + // Handle mismatched counts (more values than names, or vice versa) + var count = Math.Min(names.Count, values.Length); + if (count == 0) + return EmptyDictionary; + + var dict = new Dictionary(count); + for (int i = 0; i < count; i++) + { + dict[names[i]] = values[i]; + } + +#if NET8_0_OR_GREATER + // Use FrozenDictionary for optimal read performance on .NET 8+ + return System.Collections.Frozen.FrozenDictionary.ToFrozenDictionary(dict); +#else + return dict; +#endif + } + + private static readonly IReadOnlyDictionary EmptyDictionary = +#if NET8_0_OR_GREATER + System.Collections.Frozen.FrozenDictionary.Empty; +#else + new Dictionary(); +#endif + /// /// INTERNAL API /// diff --git a/src/core/Akka/Event/MessageTemplateParser.cs b/src/core/Akka/Event/MessageTemplateParser.cs new file mode 100644 index 00000000000..be04997ad25 --- /dev/null +++ b/src/core/Akka/Event/MessageTemplateParser.cs @@ -0,0 +1,213 @@ +//----------------------------------------------------------------------- +// +// Copyright (C) 2009-2025 Lightbend Inc. +// Copyright (C) 2013-2025 .NET Foundation +// +//----------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Linq; + +namespace Akka.Event +{ + /// + /// Parses message templates to extract property names for semantic logging. + /// Supports both positional templates ({0}, {1}) and named templates ({PropertyName}). + /// Uses ThreadStatic caching for performance. + /// + internal static class MessageTemplateParser + { + [ThreadStatic] + private static LruCache? _cache; + + private const int MaxCacheSize = 1000; + + private static LruCache Cache + { + get + { + if (_cache == null) + _cache = new LruCache(MaxCacheSize); + return _cache; + } + } + + /// + /// Gets the property names from a message template. + /// For positional templates like "{0} and {1}", returns ["0", "1"]. + /// For named templates like "{UserId} logged in", returns ["UserId"]. + /// Results are cached for performance. + /// + /// The message template string + /// List of property names + public static IReadOnlyList GetPropertyNames(string template) + { + if (string.IsNullOrEmpty(template)) + return Array.Empty(); + + var hash = template.GetHashCode(); + + // Try cache first + if (Cache.TryGet(hash, out var cached) && cached.Template == template) + return cached.PropertyNames; + + // Parse and cache + var propertyNames = ParseTemplate(template); + var parsed = new ParsedTemplate(template, propertyNames); + Cache.Add(hash, parsed); + + return propertyNames; + } + + /// + /// Parses a message template to extract property names. + /// + private static IReadOnlyList ParseTemplate(string template) + { + var properties = new List(); + var length = template.Length; + var i = 0; + + while (i < length) + { + var openBrace = template.IndexOf('{', i); + if (openBrace == -1) + break; + + // Check for escaped brace {{ + if (openBrace + 1 < length && template[openBrace + 1] == '{') + { + i = openBrace + 2; + continue; + } + + var closeBrace = template.IndexOf('}', openBrace + 1); + if (closeBrace == -1) + break; // Malformed template, stop parsing + + // Note: We do NOT check for }} here. The }} escape sequence only applies to literal + // text during formatting, not during property name extraction. After finding a valid + // placeholder {Name}, any subsequent } is a literal character, not an escape. + // For example: "{UserId}}" has placeholder "UserId" followed by literal "}" + + // Extract property name + var propertyLength = closeBrace - openBrace - 1; + if (propertyLength > 0) + { + var propertyName = template.Substring(openBrace + 1, propertyLength).Trim(); + + // Remove format specifiers (e.g., {Value:N2} -> Value) + var colonIndex = propertyName.IndexOf(':'); + if (colonIndex > 0) + propertyName = propertyName.Substring(0, colonIndex).Trim(); + + // Remove alignment specifiers (e.g., {Value,10} -> Value) + var commaIndex = propertyName.IndexOf(','); + if (commaIndex > 0) + propertyName = propertyName.Substring(0, commaIndex).Trim(); + + if (!string.IsNullOrEmpty(propertyName)) + properties.Add(propertyName); + } + + i = closeBrace + 1; + } + + return properties.ToArray(); + } + } + + /// + /// Represents a parsed message template with property names. + /// + internal sealed class ParsedTemplate + { + public string Template { get; } + public IReadOnlyList PropertyNames { get; } + + public ParsedTemplate(string template, IReadOnlyList propertyNames) + { + Template = template; + PropertyNames = propertyNames; + } + } + + /// + /// Simple LRU (Least Recently Used) cache implementation. + /// + internal sealed class LruCache where TKey : notnull + { + private readonly int _maxSize; + private readonly Dictionary> _cache; + private readonly LinkedList _lruList; + + public LruCache(int maxSize) + { + _maxSize = maxSize; + _cache = new Dictionary>(maxSize); + _lruList = new LinkedList(); + } + + /// + /// Tries to get a value from the cache. + /// If found, moves the entry to the front (most recently used). + /// + public bool TryGet(TKey key, out TValue value) + { + if (_cache.TryGetValue(key, out var node)) + { + // Move to front (most recently used) + _lruList.Remove(node); + _lruList.AddFirst(node); + + value = node.Value.Value; + return true; + } + + value = default!; + return false; + } + + /// + /// Adds a value to the cache. + /// If at capacity, evicts the least recently used entry. + /// + public void Add(TKey key, TValue value) + { + // If key already exists, update it + if (_cache.TryGetValue(key, out var existingNode)) + { + _lruList.Remove(existingNode); + _cache.Remove(key); + } + // Evict oldest if at capacity + else if (_cache.Count >= _maxSize) + { + var oldest = _lruList.Last; + if (oldest != null) + { + _lruList.RemoveLast(); + _cache.Remove(oldest.Value.Key); + } + } + + // Add new entry + var entry = new CacheEntry(key, value); + var node = _lruList.AddFirst(entry); + _cache[key] = node; + } + + private struct CacheEntry + { + public TKey Key { get; } + public TValue Value { get; } + + public CacheEntry(TKey key, TValue value) + { + Key = key; + Value = value; + } + } + } +} diff --git a/src/core/Akka/Event/SemanticLogMessageFormatter.cs b/src/core/Akka/Event/SemanticLogMessageFormatter.cs new file mode 100644 index 00000000000..73c3df71dd1 --- /dev/null +++ b/src/core/Akka/Event/SemanticLogMessageFormatter.cs @@ -0,0 +1,494 @@ +//----------------------------------------------------------------------- +// +// Copyright (C) 2009-2025 Lightbend Inc. +// Copyright (C) 2013-2025 .NET Foundation +// +//----------------------------------------------------------------------- + +using System; +using System.Collections.Generic; +using System.Linq; +using System.Text; + +namespace Akka.Event +{ + /// + /// Message formatter that supports semantic logging with both positional and named templates. + /// Implements the Message Templates specification, + /// which is the language-neutral standard used by Serilog, Microsoft.Extensions.Logging, NLog, + /// and other structured logging frameworks. + /// + /// + /// Supported syntax: + /// + /// Named properties: {PropertyName} + /// Positional properties: {0}, {1} + /// Format specifiers: {Value:N2}, {Date:yyyy-MM-dd} + /// Alignment: {Value,10}, {Value,-10} + /// Escaped braces: {{ → {, }} → } + /// + /// Not supported: + /// + /// Destructuring operators: {@Object}, {$Object} (Serilog-specific) + /// Empty property names: {:N2} (invalid per spec) + /// + /// + public sealed class SemanticLogMessageFormatter : ILogMessageFormatter + { + /// + /// Gets the singleton instance of the . + /// + public static readonly SemanticLogMessageFormatter Instance = new(); + + private SemanticLogMessageFormatter() + { + } + + /// + /// Formats a log message using the specified format string and arguments. + /// + /// The format string (supports both {0} and {PropertyName} styles) + /// The arguments to format + /// The formatted message string + public string Format(string format, params object[] args) + { + return Format(format, (IEnumerable)args); + } + + /// + /// Formats a log message using the specified format string and arguments. + /// + /// The format string (supports both {0} and {PropertyName} styles) + /// The arguments to format + /// The formatted message string + public string Format(string format, IEnumerable args) + { + if (string.IsNullOrEmpty(format)) + return string.Empty; + + // Optimize: avoid ToArray() if args is already an array or IReadOnlyList + object[] argArray; + if (args == null) + { + argArray = Array.Empty(); + } + else if (args is object[] array) + { + argArray = array; + } + else if (args is IReadOnlyList readOnlyList) + { + // LogValues structs implement IReadOnlyList, use them directly + // Only convert to array for string.Format which requires object[] + var propertyNames = MessageTemplateParser.GetPropertyNames(format); + if (propertyNames.Count == 0) + return UnescapeBraces(format); + + var isPositional = propertyNames.Count > 0 && int.TryParse(propertyNames[0], out _); + + if (isPositional) + { + // string.Format requires object[], so convert here only + argArray = new object[readOnlyList.Count]; + for (int i = 0; i < readOnlyList.Count; i++) + argArray[i] = readOnlyList[i]; + + // For positional templates, use string.Format directly without catching FormatException + // to maintain backward compatibility with DefaultLogMessageFormatter behavior + return string.Format(format, argArray); + } + else + { + // Named template - use IReadOnlyList directly + return FormatNamedTemplate(format, propertyNames, readOnlyList); + } + } + else + { + argArray = args.ToArray(); + } + + if (argArray.Length == 0) + return UnescapeBraces(format); + + // Get property names from the template + var propertyNames2 = MessageTemplateParser.GetPropertyNames(format); + if (propertyNames2.Count == 0) + return UnescapeBraces(format); + + // Check if this is a positional template or named template + var isPositional2 = propertyNames2.Count > 0 && int.TryParse(propertyNames2[0], out _); + + if (isPositional2) + { + // For positional templates, use string.Format directly without catching FormatException + // to maintain backward compatibility with DefaultLogMessageFormatter behavior + return string.Format(format, argArray); + } + else + { + // Named template - do semantic substitution + return FormatNamedTemplate(format, propertyNames2, argArray); + } + } + + /// + /// Unescapes {{ to { and }} to } in a string that has no placeholders. + /// + private static string UnescapeBraces(string format) + { + // Fast path: if no escaped braces, return as-is + if (format.IndexOf('{') == -1 && format.IndexOf('}') == -1) + return format; + + var result = new StringBuilder(format.Length); + var length = format.Length; + var i = 0; + + while (i < length) + { + var ch = format[i]; + + if (ch == '{' && i + 1 < length && format[i + 1] == '{') + { + result.Append('{'); + i += 2; + } + else if (ch == '}' && i + 1 < length && format[i + 1] == '}') + { + result.Append('}'); + i += 2; + } + else + { + result.Append(ch); + i++; + } + } + + return result.ToString(); + } + + /// + /// Formats a named template by replacing {PropertyName} with values. + /// Handles escaped braces: {{ → {, }} → } + /// + private static string FormatNamedTemplate(string format, IReadOnlyList propertyNames, IReadOnlyList args) + { + var result = new StringBuilder(format.Length + args.Count * 10); + var length = format.Length; + var i = 0; + var argIndex = 0; + + while (i < length) + { + var ch = format[i]; + + // Check for escaped }} in literal text + if (ch == '}' && i + 1 < length && format[i + 1] == '}') + { + result.Append('}'); + i += 2; + continue; + } + + // Check for placeholder start + if (ch == '{') + { + // Check for escaped brace {{ + if (i + 1 < length && format[i + 1] == '{') + { + result.Append('{'); + i += 2; + continue; + } + + // Find closing brace for placeholder + var closeBrace = format.IndexOf('}', i + 1); + if (closeBrace == -1) + { + // Malformed template, append rest and break + result.Append(format.Substring(i)); + break; + } + + // Extract the placeholder content + var placeholderLength = closeBrace - i - 1; + if (placeholderLength > 0) + { + var placeholder = format.Substring(i + 1, placeholderLength).Trim(); + + // Parse placeholder: {Name,alignment:format} + // First, find the property name (before comma or colon) + var commaIndex = placeholder.IndexOf(','); + var colonIndex = placeholder.IndexOf(':'); + string propertyName; + string alignmentSpec = null; + string formatSpec = null; + + // Determine the property name endpoint + var endOfName = placeholder.Length; + if (commaIndex >= 0 && (colonIndex < 0 || commaIndex < colonIndex)) + { + // Comma comes first (or no colon) + endOfName = commaIndex; + } + else if (colonIndex >= 0) + { + // Colon comes first (or no comma) + endOfName = colonIndex; + } + + propertyName = placeholder.Substring(0, endOfName).Trim(); + + // Extract alignment if present + if (commaIndex >= 0) + { + var alignmentStart = commaIndex + 1; + var alignmentEnd = colonIndex >= 0 ? colonIndex : placeholder.Length; + alignmentSpec = placeholder.Substring(alignmentStart, alignmentEnd - alignmentStart).Trim(); + } + + // Extract format specifier if present + if (colonIndex >= 0) + { + formatSpec = placeholder.Substring(colonIndex + 1).Trim(); + } + + placeholder = propertyName; + + // Substitute the value + if (argIndex < args.Count) + { + var value = args[argIndex]; + string formattedValue; + + if (value != null) + { + // First get the string representation + var strValue = value.ToString(); + + if (strValue != null) + { + // Apply format specifier if present + if (!string.IsNullOrEmpty(formatSpec)) + { + try + { + formattedValue = string.Format($"{{0:{formatSpec}}}", value); + } + catch + { + // If formatting fails, use the plain string + formattedValue = strValue; + } + } + else + { + formattedValue = strValue; + } + } + else + { + // ToString() returned null + formattedValue = "null"; + } + } + else + { + formattedValue = "null"; + } + + // Apply alignment if present + if (!string.IsNullOrEmpty(alignmentSpec) && int.TryParse(alignmentSpec, out var alignment)) + { + formattedValue = alignment > 0 + ? formattedValue.PadLeft(alignment) + : formattedValue.PadRight(-alignment); + } + + result.Append(formattedValue); + argIndex++; + } + else + { + // Not enough args, keep the placeholder + result.Append('{').Append(placeholder).Append('}'); + } + } + + i = closeBrace + 1; + } + else + { + // Regular character + result.Append(ch); + i++; + } + } + + return result.ToString(); + } + + /// + /// Formats a named template by replacing {PropertyName} with values. + /// Handles escaped braces: {{ → {, }} → } + /// + private static string FormatNamedTemplate(string format, IReadOnlyList propertyNames, object[] args) + { + var result = new StringBuilder(format.Length + args.Length * 10); + var length = format.Length; + var i = 0; + var argIndex = 0; + + while (i < length) + { + var ch = format[i]; + + // Check for escaped }} in literal text + if (ch == '}' && i + 1 < length && format[i + 1] == '}') + { + result.Append('}'); + i += 2; + continue; + } + + // Check for placeholder start + if (ch == '{') + { + // Check for escaped brace {{ + if (i + 1 < length && format[i + 1] == '{') + { + result.Append('{'); + i += 2; + continue; + } + + // Find closing brace for placeholder + var closeBrace = format.IndexOf('}', i + 1); + if (closeBrace == -1) + { + // Malformed template, append rest and break + result.Append(format.Substring(i)); + break; + } + + // Extract the placeholder content + var placeholderLength = closeBrace - i - 1; + if (placeholderLength > 0) + { + var placeholder = format.Substring(i + 1, placeholderLength).Trim(); + + // Parse placeholder: {Name,alignment:format} + // First, find the property name (before comma or colon) + var commaIndex = placeholder.IndexOf(','); + var colonIndex = placeholder.IndexOf(':'); + string propertyName; + string alignmentSpec = null; + string formatSpec = null; + + // Determine the property name endpoint + var endOfName = placeholder.Length; + if (commaIndex >= 0 && (colonIndex < 0 || commaIndex < colonIndex)) + { + // Comma comes first (or no colon) + endOfName = commaIndex; + } + else if (colonIndex >= 0) + { + // Colon comes first (or no comma) + endOfName = colonIndex; + } + + propertyName = placeholder.Substring(0, endOfName).Trim(); + + // Extract alignment if present + if (commaIndex >= 0) + { + var alignmentStart = commaIndex + 1; + var alignmentEnd = colonIndex >= 0 ? colonIndex : placeholder.Length; + alignmentSpec = placeholder.Substring(alignmentStart, alignmentEnd - alignmentStart).Trim(); + } + + // Extract format specifier if present + if (colonIndex >= 0) + { + formatSpec = placeholder.Substring(colonIndex + 1).Trim(); + } + + placeholder = propertyName; + + // Substitute the value + if (argIndex < args.Length) + { + var value = args[argIndex]; + string formattedValue; + + if (value != null) + { + // First get the string representation + var strValue = value.ToString(); + + if (strValue != null) + { + // Apply format specifier if present + if (!string.IsNullOrEmpty(formatSpec)) + { + try + { + formattedValue = string.Format($"{{0:{formatSpec}}}", value); + } + catch + { + // If formatting fails, use the plain string + formattedValue = strValue; + } + } + else + { + formattedValue = strValue; + } + } + else + { + // ToString() returned null + formattedValue = "null"; + } + } + else + { + formattedValue = "null"; + } + + // Apply alignment if present + if (!string.IsNullOrEmpty(alignmentSpec) && int.TryParse(alignmentSpec, out var alignment)) + { + formattedValue = alignment > 0 + ? formattedValue.PadLeft(alignment) + : formattedValue.PadRight(-alignment); + } + + result.Append(formattedValue); + argIndex++; + } + else + { + // Not enough args, keep the placeholder + result.Append('{').Append(placeholder).Append('}'); + } + } + + i = closeBrace + 1; + } + else + { + // Regular character + result.Append(ch); + i++; + } + } + + return result.ToString(); + } + } +} diff --git a/src/core/Akka/Event/StandardOutLogger.cs b/src/core/Akka/Event/StandardOutLogger.cs index 037cab22c41..1215fffedae 100644 --- a/src/core/Akka/Event/StandardOutLogger.cs +++ b/src/core/Akka/Event/StandardOutLogger.cs @@ -6,6 +6,7 @@ //----------------------------------------------------------------------- using System; +using System.Linq; using Akka.Actor; using Akka.Util; using System.Text; @@ -126,7 +127,7 @@ internal static void PrintLogEvent(LogEvent logEvent, LogFilterEvaluator filter) // short circuit if we're not going to print this message if (!filter.ShouldTryKeepMessage(logEvent, out var expandedLogMessage)) return; - + ConsoleColor? color = null; if (UseColors)