Akka.Event: restore missing log data #7256

Aaronontheweb · 2024-06-14T01:03:24Z

Changes

Fixes #7255

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 Akka.Logging: v1.5.21 appears to have truncated log source, timestamps, etc from all log messages #7255
Changes in public API reviewed, if any.

Aaronontheweb

Detailed my reproduction steps

Aaronontheweb · 2024-06-14T02:12:45Z

build.fsx

@@ -55,7 +55,7 @@ let runIncrementally = hasBuildParam "incremental"
 let incrementalistReport = output @@ "incrementalist.txt"

 // Configuration values for tests
-let testNetFrameworkVersion = "net471"
+let testNetFrameworkVersion = "net48"


Upgraded to .NET 4.8 so we could use newer versions of Verify, which had DateTime scrubbing. I ended up not needing it but I don't think it hurts anything given that this only affects the test suite.

Aaronontheweb · 2024-06-14T02:13:26Z

src/Directory.Build.props

@@ -18,8 +18,8 @@
    <LangVersion>11.0</LangVersion>
  </PropertyGroup>
  <PropertyGroup>
-    <XunitVersion>2.5.3</XunitVersion>
-    <XunitRunnerVersion>2.5.3</XunitRunnerVersion>
+    <XunitVersion>2.8.1</XunitVersion>


Redundant - we already use these newer versions on dev but I had to capture what the logs originally should have looked like on v1.5.20, where we had not yet performed these upgrades. Verify.Xunit required the newer versions.

Aaronontheweb · 2024-06-14T02:13:45Z

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

@@ -28,7 +28,6 @@

 namespace Akka.API.Tests
 {
-    [UsesVerify]


Obsolete in the latest version of Verify

Aaronontheweb · 2024-06-14T02:15:01Z

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

+        Sys.EventStream.Subscribe(probe.Ref, typeof(LogEvent));
+
+        // act
+        using (new OutputRedirector(filePath))


The error in #7255 was caused not by the formatter on the message changing, but by the fact that we started calling .ToString on the wrong thing in v1.5.21. This test is designed to capture STDOUT and verify against that, so either type of mistake will be caught in the future should it occur again.

Aaronontheweb · 2024-06-14T02:15:20Z

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

+        var text = File.ReadAllText(filePath);
+
+        // need to sanitize the thread id
+        text = SanitizeDateTime(text);


Scrub thread ids and datetimes, since these are unstable run-per-run even if everything is working normally.

Aaronontheweb · 2024-06-14T02:15:32Z

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

@@ -14,6 +14,7 @@ public static class ModuleInit
    [ModuleInitializer]
    public static void Init()
    {
+        VerifyDiffPlex.Initialize();


Force DiffPlex to start once at boot.

Aaronontheweb · 2024-06-14T02:15:50Z

src/core/Akka.API.Tests/verify/DefaultLogFormatSpec.ShouldUseDefaultLogFormat.Net.verified.txt

+[DEBUG][DateTime][Thread 0001][ActorSystem(test)] This is a test 1 cheese
+[INFO][DateTime][Thread 0001][ActorSystem(test)] This is a test 1
+[WARNING][DateTime][Thread 0001][ActorSystem(test)] This is a test 1
+[ERROR][DateTime][Thread 0001][ActorSystem(test)] This is a test 1


No idea why the stack trace logs don't show up on .NET Framework, but they do on .NET 8

Aaronontheweb

Introduced the fix and detailed my changes - worried a bit about the .NET Framework 4.7.1 -> 4.8 movement breaking some stuff on the build server but we'll see.

Aaronontheweb · 2024-06-14T02:53:40Z

build-system/azure-pipeline.template.yaml

+          TargetFolder: '$(Build.ArtifactStagingDirectory)/verify'
+        displayName: 'Copy .received. files to artifact staging directory'
+
+      - task: PublishBuildArtifacts@1


Add .received files from Verify as a build output whenever we have a test failure.

Aaronontheweb · 2024-06-14T03:00:26Z

src/core/Akka/Event/LogFilter.cs

@@ -191,7 +191,7 @@ public virtual bool ShouldTryKeepMessage(LogEvent evt, out string expandedLogMes
        else
        {
            // allocate the message just once
-            var nullCheck = evt.Message.ToString();


These are the fixes here - we were only looking at the message, not the entire log string.

Aaronontheweb · 2024-06-14T03:00:49Z

src/core/Akka/Event/LogFilter.cs

@@ -225,7 +225,7 @@ private EmptyLogFilterEvaluator() : base(Array.Empty<LogFilterBase>())

        public override bool ShouldTryKeepMessage(LogEvent evt, out string expandedLogMessage)
        {
-            expandedLogMessage = evt.Message.ToString()!;


This is the fix for most use cases, when users don't have any log filtering enabled.

has trouble running on Linux

Aaronontheweb · 2024-06-14T03:16:06Z

src/core/Akka.Docs.Tests/Streams/RestartDocTests.cs

@@ -16,6 +16,7 @@

 namespace DocsExamples.Streams
 {
+#if NETCOREAPP


Caused a grumble on Linux, which caused DocFx validation to fail

Aaronontheweb · 2024-06-14T13:32:08Z

Looks like my reproduction spec can be racy - going to take a look at it and see what I can do about that.

Aaronontheweb · 2024-06-14T13:33:24Z

Akka.Remote.Tests.Transport.DotNettySslSupportSpec.If_EnableSsl_configuration_is_true_but_not_valid_certificate_is_provided_than_ArgumentNullException_should_be_thrown <- this spec appears to have been broken as a result of upgrading to .NET 4.8

Aaronontheweb · 2024-06-14T15:00:19Z

VerifyException : Directory: D:\a\1\s\src\core\Akka.API.Tests\verify
NotEqual:
  - Received: DefaultLogFormatSpec.ShouldUseDefaultLogFormat.DotNet8_0.received.txt
    Verified: DefaultLogFormatSpec.ShouldUseDefaultLogFormat.DotNet.verified.txt

FileContent:

NotEqual:

Received: DefaultLogFormatSpec.ShouldUseDefaultLogFormat.DotNet8_0.received.txt
Verified: DefaultLogFormatSpec.ShouldUseDefaultLogFormat.DotNet.verified.txt
Compare Result:
- [DEBUG][DateTime][Thread 0001][ActorSystem(test)] This is a test 1 cheese
+ emptyString
- [INFO][DateTime][Thread 0001][ActorSystem(test)] This is a test 1
- [WARNING][DateTime][Thread 0001][ActorSystem(test)] This is a test 1
- [ERROR][DateTime][Thread 0001][ActorSystem(test)] This is a test 1
-

Output from Verfiy.received:

emptyString

I think what we have here is a race condition between the EventStream and the StandardOutLogger actually completing all of its processing. Might need to retool the system we're using to intercept the output.

Arkatufus

LGTM

Aaronontheweb added 2 commits June 13, 2024 19:55

added reproduction for akkadotnet#7255

2741bef

trying to get Verify to work

5562238

Aaronontheweb added tests logging labels Jun 14, 2024

Aaronontheweb added 2 commits June 13, 2024 21:09

upgraded Verify and added full log output repro

a250cc9

added .NET 4.8 upgrades

f31e9e6

Aaronontheweb commented Jun 14, 2024

View reviewed changes

Aaronontheweb added 5 commits June 13, 2024 21:32

add verify output as a build artifact

ed0ebba

fixing ci/cd

585668c

create unique name for each Verify artifact

0a41a38

Merge branch 'dev' into fix-7255-log-data

098a265

close akkadotnet#7255

c190a4f

Aaronontheweb commented Jun 14, 2024

View reviewed changes

Aaronontheweb added 3 commits June 13, 2024 22:05

disable flaky spec on .NET 4.8

c8c40fa

has trouble running on Linux

simplify artifact publication

a3bcb43

hardening LogFormatSpec

668d176

Aaronontheweb marked this pull request as ready for review June 14, 2024 03:11

Aaronontheweb changed the title ~~[WIP] restore missing log data~~ Akka.Event: restore missing log data Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

View reviewed changes

Aaronontheweb added 4 commits June 14, 2024 10:14

hardened DefaultLogFormatSpec

1e3cfc7

fixed failures on EnableSsl spec

f18eced

fixed skipping .NET48 unfriendly spec

50046d4

no longer need to skip this

0dc42fe

Arkatufus approved these changes Jun 14, 2024

View reviewed changes

Arkatufus enabled auto-merge (squash) June 14, 2024 17:20

Aaronontheweb disabled auto-merge June 14, 2024 17:23

Aaronontheweb merged commit be4ed4d into akkadotnet:dev Jun 14, 2024
9 of 12 checks passed

Aaronontheweb deleted the fix-7255-log-data branch June 14, 2024 17:24

Aaronontheweb mentioned this pull request Jun 14, 2024

added v1.5.25 release notes #7257

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Akka.Event: restore missing log data #7256

Akka.Event: restore missing log data #7256

Aaronontheweb commented Jun 14, 2024 •

edited

Loading

Aaronontheweb left a comment

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb left a comment

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

Arkatufus left a comment

Akka.Event: restore missing log data #7256

Akka.Event: restore missing log data #7256

Conversation

Aaronontheweb commented Jun 14, 2024 • edited Loading

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

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

Aaronontheweb commented Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

Aaronontheweb commented Jun 14, 2024

Arkatufus left a comment

Choose a reason for hiding this comment

Aaronontheweb commented Jun 14, 2024 •

edited

Loading