Skip to content

Commit b85078f

Browse files
feat: Add native semantic logging support with property extraction (#7933)
* 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<object> (LogValues<T> 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 f9a2d2c. 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 1c58a6b. 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 <[email protected]>
1 parent 747abfc commit b85078f

17 files changed

+2298
-9
lines changed

src/benchmark/Akka.Benchmarks/Logging/SemanticLoggingBenchmarks.cs

Lines changed: 534 additions & 0 deletions
Large diffs are not rendered by default.

src/core/Akka.API.Tests/LogFormatSpec.cs

Lines changed: 57 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -32,9 +32,9 @@ public DefaultLogFormatSpec() : base(CustomLoggerSetup())
3232
{
3333
_logger = (CustomLogger)Sys.Settings.StdoutLogger;
3434
}
35-
35+
3636
private readonly CustomLogger _logger;
37-
37+
3838
public class CustomLogger : StandardOutLogger
3939
{
4040
protected override void Log(object message)
@@ -44,13 +44,13 @@ protected override void Log(object message)
4444
{
4545
_events.Add(e);
4646
}
47-
47+
4848
}
49-
49+
5050
private readonly ConcurrentBag<LogEvent> _events = new();
5151
public IReadOnlyCollection<LogEvent> Events => _events;
5252
}
53-
53+
5454
public static ActorSystemSetup CustomLoggerSetup()
5555
{
5656
var hocon = @$"
@@ -115,6 +115,58 @@ await AwaitConditionAsync(() =>
115115
await Verifier.Verify(text);
116116
}
117117

118+
[Fact]
119+
public async Task ShouldHandleSemanticLogEdgeCases()
120+
{
121+
// arrange
122+
var filePath = Path.GetTempFileName();
123+
124+
// act
125+
using (new OutputRedirector(filePath))
126+
{
127+
// Named properties
128+
Sys.Log.Debug("User {UserId} logged in from {IpAddress}", 12345, "192.168.1.1");
129+
Sys.Log.Info("Processing order {OrderId} for customer {CustomerId}", "ORD-001", "CUST-999");
130+
131+
// Positional properties (old style)
132+
Sys.Log.Warning("Processing item {0} of {1}", 5, 10);
133+
134+
// Mixed types - use F2 instead of C for culture-independent output
135+
Sys.Log.Info("Order total is ${Amount:F2} with {ItemCount} items", 123.45m, 3);
136+
137+
// Edge cases
138+
Sys.Log.Debug("Empty template");
139+
Sys.Log.Info("Single property {Value}", 42);
140+
Sys.Log.Warning("Null value: {NullValue}", null);
141+
Sys.Log.Error("Exception occurred for user {UserId}", 999);
142+
143+
// Special characters and escaping
144+
Sys.Log.Debug("Path: {FilePath}, Size: {FileSize} bytes", @"C:\temp\file.txt", 1024);
145+
146+
// Boolean and date types - use explicit date format for culture-independent output
147+
Sys.Log.Info("User {Username} is active: {IsActive}, joined on {JoinDate:yyyy-MM-dd}", "john.doe", true, DateTime.Parse("2024-01-15"));
148+
149+
// Long strings and alignment
150+
Sys.Log.Debug("Request from {RemoteAddress} to endpoint {Endpoint} took {DurationMs}ms", "192.168.1.100:54321", "/api/v1/users", 250);
151+
152+
// force all logs to be received - wait for the last log message
153+
await AwaitConditionAsync(() => Task.FromResult(_logger.Events.Any(e => e.Message.ToString()!.Contains("took 250ms"))), TimeSpan.FromSeconds(5));
154+
}
155+
156+
// assert
157+
// ReSharper disable once MethodHasAsyncOverload
158+
var text = File.ReadAllText(filePath);
159+
160+
// need to sanitize the thread id and timestamps
161+
text = SanitizeDateTime(text);
162+
text = SanitizeThreadNumber(text);
163+
text = SanitizeTestEventListener(text);
164+
text = SanitizeDefaultLoggersStarted(text);
165+
text = SanitizeCustomLoggerRemoved(text);
166+
167+
await Verifier.Verify(text);
168+
}
169+
118170
private static string SanitizeDefaultLoggersStarted(string logs)
119171
{
120172
var pattern = @"^.*Default Loggers started.*$\r?\n?";

src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.DotNet.verified.txt

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3472,6 +3472,17 @@ namespace Akka.Event
34723472
public abstract Akka.Event.LogLevel LogLevel();
34733473
public override string ToString() { }
34743474
}
3475+
[System.Runtime.CompilerServices.NullableAttribute(0)]
3476+
public class static LogEventExtensions
3477+
{
3478+
public static System.Collections.Generic.IEnumerable<object> GetParameters(this Akka.Event.LogEvent evt) { }
3479+
public static System.Collections.Generic.IReadOnlyList<string> GetPropertyNames(this Akka.Event.LogEvent evt) { }
3480+
public static string GetTemplate(this Akka.Event.LogEvent evt) { }
3481+
public static bool TryGetProperties(this Akka.Event.LogEvent evt, [System.Runtime.CompilerServices.NullableAttribute(new byte[] {
3482+
2,
3483+
1,
3484+
1})] out System.Collections.Generic.IReadOnlyDictionary<string, object> properties) { }
3485+
}
34753486
public abstract class LogFilterBase : Akka.Actor.INoSerializationVerificationNeeded, Akka.Event.IDeadLetterSuppression
34763487
{
34773488
protected LogFilterBase() { }
@@ -3531,6 +3542,8 @@ namespace Akka.Event
35313542
protected readonly Akka.Event.ILogMessageFormatter Formatter;
35323543
public LogMessage(Akka.Event.ILogMessageFormatter formatter, string format) { }
35333544
public string Format { get; }
3545+
public System.Collections.Generic.IReadOnlyList<string> PropertyNames { get; }
3546+
public System.Collections.Generic.IReadOnlyDictionary<string, object> GetProperties() { }
35343547
[Akka.Annotations.InternalApiAttribute()]
35353548
public abstract System.Collections.Generic.IEnumerable<object> Parameters();
35363549
[Akka.Annotations.InternalApiAttribute()]
@@ -3708,6 +3721,12 @@ namespace Akka.Event
37083721
public override Akka.Event.LogFilterType FilterType { get; }
37093722
public override Akka.Event.LogFilterDecision ShouldKeepMessage(Akka.Event.LogEvent content, [System.Runtime.CompilerServices.NullableAttribute(2)] string expandedMessage = null) { }
37103723
}
3724+
public sealed class SemanticLogMessageFormatter : Akka.Event.ILogMessageFormatter
3725+
{
3726+
public static readonly Akka.Event.SemanticLogMessageFormatter Instance;
3727+
public string Format(string format, params object[] args) { }
3728+
public string Format(string format, System.Collections.Generic.IEnumerable<object> args) { }
3729+
}
37113730
public class StandardOutLogger : Akka.Event.MinimalLogger
37123731
{
37133732
public StandardOutLogger() { }

src/core/Akka.API.Tests/verify/CoreAPISpec.ApproveCore.Net.verified.txt

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3483,6 +3483,17 @@ namespace Akka.Event
34833483
public abstract Akka.Event.LogLevel LogLevel();
34843484
public override string ToString() { }
34853485
}
3486+
[System.Runtime.CompilerServices.NullableAttribute(0)]
3487+
public class static LogEventExtensions
3488+
{
3489+
public static System.Collections.Generic.IEnumerable<object> GetParameters(this Akka.Event.LogEvent evt) { }
3490+
public static System.Collections.Generic.IReadOnlyList<string> GetPropertyNames(this Akka.Event.LogEvent evt) { }
3491+
public static string GetTemplate(this Akka.Event.LogEvent evt) { }
3492+
public static bool TryGetProperties(this Akka.Event.LogEvent evt, [System.Runtime.CompilerServices.NullableAttribute(new byte[] {
3493+
2,
3494+
1,
3495+
1})] out System.Collections.Generic.IReadOnlyDictionary<string, object> properties) { }
3496+
}
34863497
public abstract class LogFilterBase : Akka.Actor.INoSerializationVerificationNeeded, Akka.Event.IDeadLetterSuppression
34873498
{
34883499
protected LogFilterBase() { }
@@ -3542,6 +3553,8 @@ namespace Akka.Event
35423553
protected readonly Akka.Event.ILogMessageFormatter Formatter;
35433554
public LogMessage(Akka.Event.ILogMessageFormatter formatter, string format) { }
35443555
public string Format { get; }
3556+
public System.Collections.Generic.IReadOnlyList<string> PropertyNames { get; }
3557+
public System.Collections.Generic.IReadOnlyDictionary<string, object> GetProperties() { }
35453558
[Akka.Annotations.InternalApiAttribute()]
35463559
public abstract System.Collections.Generic.IEnumerable<object> Parameters();
35473560
[Akka.Annotations.InternalApiAttribute()]
@@ -3717,6 +3730,12 @@ namespace Akka.Event
37173730
public override Akka.Event.LogFilterType FilterType { get; }
37183731
public override Akka.Event.LogFilterDecision ShouldKeepMessage(Akka.Event.LogEvent content, [System.Runtime.CompilerServices.NullableAttribute(2)] string expandedMessage = null) { }
37193732
}
3733+
public sealed class SemanticLogMessageFormatter : Akka.Event.ILogMessageFormatter
3734+
{
3735+
public static readonly Akka.Event.SemanticLogMessageFormatter Instance;
3736+
public string Format(string format, params object[] args) { }
3737+
public string Format(string format, System.Collections.Generic.IEnumerable<object> args) { }
3738+
}
37203739
public class StandardOutLogger : Akka.Event.MinimalLogger
37213740
{
37223741
public StandardOutLogger() { }
Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] User 12345 logged in from 192.168.1.1
2+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Processing order ORD-001 for customer CUST-999
3+
[WARNING][DateTime][Thread 0001][ActorSystem(test)] Processing item 5 of 10
4+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Order total is $123.45 with 3 items
5+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Empty template
6+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Single property 42
7+
[WARNING][DateTime][Thread 0001][ActorSystem(test)] Null value: {NullValue}
8+
[ERROR][DateTime][Thread 0001][ActorSystem(test)] Exception occurred for user 999
9+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Path: C:\temp\file.txt, Size: 1024 bytes
10+
[INFO][DateTime][Thread 0001][ActorSystem(test)] User john.doe is active: True, joined on 2024-01-15
11+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Request from 192.168.1.100:54321 to endpoint /api/v1/users took 250ms
Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,11 @@
1+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] User 12345 logged in from 192.168.1.1
2+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Processing order ORD-001 for customer CUST-999
3+
[WARNING][DateTime][Thread 0001][ActorSystem(test)] Processing item 5 of 10
4+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Order total is $123.45 with 3 items
5+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Empty template
6+
[INFO][DateTime][Thread 0001][ActorSystem(test)] Single property 42
7+
[WARNING][DateTime][Thread 0001][ActorSystem(test)] Null value: {NullValue}
8+
[ERROR][DateTime][Thread 0001][ActorSystem(test)] Exception occurred for user 999
9+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Path: C:\temp\file.txt, Size: 1024 bytes
10+
[INFO][DateTime][Thread 0001][ActorSystem(test)] User john.doe is active: True, joined on 2024-01-15
11+
[DEBUG][DateTime][Thread 0001][ActorSystem(test)] Request from 192.168.1.100:54321 to endpoint /api/v1/users took 250ms

src/core/Akka.TestKit/EventFilter/Internal/EventFilterBase.cs

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -87,8 +87,26 @@ protected virtual void OnEventMatched(LogEvent logEvent)
8787
/// <returns>TBD</returns>
8888
protected bool InternalDoMatch(string src, object? msg)
8989
{
90+
// Check source matcher first (fast path)
91+
if (!_sourceMatcher.IsMatch(src))
92+
return false;
93+
94+
// For semantic logging support, try matching against both the formatted message
95+
// and the unformatted template pattern
96+
if (msg is LogMessage logMessage)
97+
{
98+
// Try matching against the template pattern first (e.g., "User {UserId} logged in")
99+
if (_messageMatcher.IsMatch(logMessage.Format))
100+
return true;
101+
102+
// Fall back to matching the formatted message (e.g., "User 12345 logged in")
103+
var formattedMsg = logMessage.ToString() ?? "null";
104+
return _messageMatcher.IsMatch(formattedMsg);
105+
}
106+
107+
// Non-semantic logging or legacy messages
90108
var msgstr = msg == null ? "null" : msg.ToString() ?? "null";
91-
return _sourceMatcher.IsMatch(src) && _messageMatcher.IsMatch(msgstr);
109+
return _messageMatcher.IsMatch(msgstr);
92110
}
93111

94112
/// <summary>

src/core/Akka.Tests/Configuration/ConfigurationSpec.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ public void The_default_configuration_file_contain_all_configuration_properties(
5050
settings.LogDeadLetters.ShouldBe(10);
5151
settings.LogDeadLettersDuringShutdown.ShouldBeFalse();
5252
settings.LogDeadLettersSuspendDuration.ShouldBe(TimeSpan.FromMinutes(5));
53-
settings.LogFormatter.Should().BeOfType<DefaultLogMessageFormatter>();
53+
settings.LogFormatter.Should().BeOfType<SemanticLogMessageFormatter>();
5454

5555
settings.ProviderClass.ShouldBe(typeof (LocalActorRefProvider).FullName);
5656
settings.SupervisorStrategyClass.ShouldBe(typeof (DefaultSupervisorStrategy).FullName);

0 commit comments

Comments
 (0)