Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place #7179

Aaronontheweb · 2024-04-29T16:04:53Z

Changes

Fixes #7097 and probably lots of other usability issues.

The goal behind this system is to prevent Akka.NET LogEvents from being emitted in the first place in the event that their data is not useful. This should allow developers to do things like akka.LOGLEVEL=DEBUG without getting absolutely flooded with noise from busy parts of the system like Akka.Remote, Akka.Streams, and so on.

The general idea is to pass in a new Setup class:

/// <summary>
/// Used to specify filters that can be used to curtail noise from sources in the Akka.NET log stream.
/// </summary>
public sealed class LogFilterSetup : Setup
{
    public LogFilterBase[] Filters { get; }
    
    public LogFilterEvaluator CreateEvaluator() => new(Filters);

    public LogFilterSetup(LogFilterBase[] filters)
    {
        Filters = filters;
    }
}

These LogFilterBase types are intended to be simple functions, but while taking into account some easy performance considerations:

public abstract class LogFilterBase : INoSerializationVerificationNeeded, IDeadLetterSuppression
{
    /// <summary>
    /// Which part of the log message this filter is evaluating?
    /// </summary>
    /// <remarks>
    /// This actually has a performance implication - if we're filtering on the source, which
    /// is already fully "expanded" into its final string representation, we can try to fail fast
    /// on that without any additional allocations.
    ///
    /// If we're filtering on the message, we have to fully expand the log message first which
    /// involves allocations. Users on really tight performance budgets should be aware of this.
    /// </remarks>
    public abstract LogFilterType FilterType { get; }

    /// <summary>
    /// Returns <c>true</c> if the message should be kept, <c>false</c> if it should be dropped.
    /// </summary>
    /// <param name="evt">The <see cref="LogEvent"/> being evaluated.</param>
    /// <remarks>
    /// If there are multiple filters, all of them must return <c>true</c> for the message to be kept.
    /// </remarks>
    public abstract bool ShouldKeepMessage(LogEvent evt);

    /// <summary>
    /// Fast path designed to avoid allocating strings if we're filtering on the message content.
    /// </summary>
    /// <param name="part">The part of the message to evaluate.</param>
    /// <param name="content">Usually the fully expanded message content.</param>
    public abstract LogFilterDecision ShouldKeepMessage(LogFilterType part, string content);
}

I'm even including a LogFilterBuilder that should make it easy to construct these using a simple builder pattern. For a log to be printed, all filters must evaluate to true. Will include some examples of this below.

Checklist

For significant changes, please ensure that the following have been completed (delete if not relevant):

This change follows the Akka.NET API Compatibility Guidelines.
This change follows the Akka.NET Wire Compatibility Guidelines.
I have reviewed my own pull request.
Design discussion issue Enable debug logging for ShardCoordinator/ShardRegion/Shard actors #7097
Changes in public API reviewed, if any.
I have added website documentation for this feature.

close akkadotnet#7097

Aaronontheweb

Detailed my changes

Aaronontheweb · 2024-04-29T19:24:36Z

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

@@ -1725,6 +1725,7 @@ namespace Akka.Actor
        public int LogDeadLetters { get; }
        public bool LogDeadLettersDuringShutdown { get; }
        public System.TimeSpan LogDeadLettersSuspendDuration { get; }
+        public Akka.Event.LogFilterEvaluator LogFilter { get; }


New setting - this is where the log filter actually lives. Any custom logging plugin can access it this way.

Aaronontheweb · 2024-04-29T19:25:42Z

src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs

+// ReSharper disable once ClassNeverInstantiated.Global
+public class LogFilterEvaluatorSpecs
+{
+    public class LogFilterSetupSpecs : AkkaSpec


End to end specs - I can't easily intercept the default output from the StandardOutWriter so I'm swapping in my own MinimalLogger implementation and testing the results using that at the end. Not 100% clean, but close enough.

Aaronontheweb · 2024-04-29T19:27:09Z

src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs

+            loggingAdapter2.Warning("baz");
+
+            // expect only the last message to be received
+            ReceiveN(3);


Log events will still hit the EventStream - the filter runs at the layer beneath this. AND THAT IS IMPORTANT: if we have the log filter layer running at this layer, at the point where LogEvents are EMITTED, this WILL KILL PERFORMANCE.

Instead, we make the decision about whether or not to keep / include a log at the layer right before the log is rendered. This is the correct place to do this.

Anyway, that's why we still receive all 3 log events.

Aaronontheweb · 2024-04-29T19:28:00Z

src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs

+            ReceiveN(3);
+
+            // check that the last message was the one that was allowed through
+            _logger.Events.Count.Should().Be(1);


The real logger should only have recorded the 1 log that passes both filters.

Aaronontheweb · 2024-04-29T19:28:20Z

src/core/Akka.Tests/Loggers/LogFilterEvaluatorSpecs.cs

+        }
+    }
+
+    public class LogSourceCases


The rest of these test cases are really just testing the default Regex used by the LogFilterBuilder.

Aaronontheweb · 2024-04-29T19:57:44Z

src/core/Akka/Event/LogFilter.cs

+            {
+                switch (filter.FilterType)
+                {
+                    case LogFilterType.Source:


A single vote cast for LogFilterDecision.Drop is all it takes for us to bail out.

Aaronontheweb · 2024-04-29T19:57:56Z

src/core/Akka/Event/LogFilter.cs

+        // expand the message if we haven't already
+        // NOTE: might result in duplicate allocations in third party logging libraries. They'll have to adjust their
+        // code accordingly after this feature ships.
+        expandedLogMessage = (string.IsNullOrEmpty(expandedLogMessage) ? evt.Message.ToString() : expandedLogMessage)!;


Have to expand the log down here, since we're keeping it.

Aaronontheweb · 2024-04-29T19:58:24Z

src/core/Akka/Event/StandardOutLogger.cs


 namespace Akka.Event
 {
    public abstract class MinimalLogger : MinimalActorRef
    {
+        public LogFilterEvaluator Filter { get; internal set; } = LogFilterEvaluator.NoFilters;


Default setting, which maintains previous behavior.

Aaronontheweb · 2024-04-29T19:58:34Z

src/core/Akka/Event/StandardOutLogger.cs

        {
            try
            {
+                // short circuit if we're not going to print this message
+                if (!filter.ShouldTryKeepMessage(logEvent, out var expandedLogMessage))
+                    return;


Self-explanatory.

Aaronontheweb · 2024-04-29T19:58:43Z

src/core/Akka/Event/StandardOutLogger.cs

@@ -144,7 +149,7 @@ internal static void PrintLogEvent(LogEvent logEvent)
                    }
                }

-                StandardOutWriter.WriteLine(logEvent.ToString(), color);
+                StandardOutWriter.WriteLine(expandedLogMessage, color);


Avoid expanding the log a second time.

Aaronontheweb · 2024-04-29T20:01:59Z

Going to leave this PR open for comments for a while before it gets merged in

Aaronontheweb · 2024-04-29T20:06:27Z

Also: documentation. Will add it once I get review comments.

Arkatufus

LGTM

Aaronontheweb · 2024-05-13T16:54:08Z

I still need to do API approvals here

Aaronontheweb added 2 commits April 29, 2024 10:58

create LogFilter infrastructure

f8bb385

Create evaluator from setup

26d426a

close akkadotnet#7097

Aaronontheweb added akka-actor logging api-change labels Apr 29, 2024

Aaronontheweb mentioned this pull request Apr 29, 2024

Enable debug logging for ShardCoordinator/ShardRegion/Shard actors #7097

Closed

Aaronontheweb added 8 commits April 29, 2024 11:21

added sanity checks for Regex-based rules

1b817a3

integrated LogFilterSetup into Settings and StandardOutLogger

076b77a

simplifying

09e2e9b

added accurate end2end unit test

7f804a8

added API approvals

f430b55

removed unnecessary API from LogFilterBase

ac0372b

small perf optimization for default cases

b06ad4a

fixed bug with blended filter types

6518cfa

Aaronontheweb commented Apr 29, 2024

View reviewed changes

Aaronontheweb marked this pull request as ready for review April 29, 2024 19:58

Aaronontheweb changed the title ~~[WIP] Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place~~ Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place Apr 29, 2024

Merge branch 'dev' into log-filtering-system

8f28210

Aaronontheweb added this to the 1.5.21 milestone Apr 29, 2024

Arkatufus approved these changes Apr 30, 2024

View reviewed changes

Arkatufus and others added 2 commits April 30, 2024 22:19

Merge branch 'dev' into log-filtering-system

12feb8c

Merge branch 'dev' into log-filtering-system

a0c43fa

Aaronontheweb added 5 commits May 22, 2024 14:11

added API approvals

0dbc913

fixed race condition with tests

e5d0d06

updated APIs to be more expansive

1c3c6d0

added docs

994035a

Merge branch 'dev' into log-filtering-system

498c4f8

Arkatufus enabled auto-merge (squash) May 22, 2024 20:33

fixed reference to samples

0da0874

Arkatufus disabled auto-merge May 22, 2024 20:50

fixed markdown linting rule

8d5337e

Aaronontheweb enabled auto-merge (squash) May 22, 2024 20:59

Aaronontheweb disabled auto-merge May 22, 2024 21:52

Aaronontheweb merged commit d1ed226 into akkadotnet:dev May 22, 2024
9 of 12 checks passed

Aaronontheweb deleted the log-filtering-system branch May 22, 2024 21:52

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place #7179

Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place #7179

Aaronontheweb commented Apr 29, 2024 •

edited

Aaronontheweb left a comment

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb Apr 29, 2024

Aaronontheweb commented Apr 29, 2024

Aaronontheweb commented Apr 29, 2024

Arkatufus left a comment

Aaronontheweb commented May 13, 2024

Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place #7179

Akka.Event: add log filtering system to prevent Akka.NET logs from being emitted in first place #7179

Conversation

Aaronontheweb commented Apr 29, 2024 • edited

Changes

Checklist

Aaronontheweb left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Aaronontheweb commented Apr 29, 2024

Aaronontheweb commented Apr 29, 2024

Arkatufus left a comment

Choose a reason for hiding this comment

Aaronontheweb commented May 13, 2024

Aaronontheweb commented Apr 29, 2024 •

edited