Fix faulty AddLogger in LoggingBus #6028

Arkatufus · 2022-07-01T16:22:06Z

Exception handling inside AddLogger is wrong

src/core/Akka/Event/LoggingBus.cs

Aaronontheweb

Have some questions and one minor requested change

src/core/Akka/Event/LoggingBus.cs

Aaronontheweb · 2022-07-18T12:25:26Z

@Arkatufus this will need to be sent to v1.5 as well?

Arkatufus · 2022-07-18T20:36:22Z

@Aaronontheweb yeah, I'll make a port when this is done

Arkatufus · 2022-07-19T13:45:42Z

This is the original fix:
a155dcc#diff-d271e591ce53138713aa0d7b825006f40bc2ed5591cd8cb00d7247d7f4ea900fR110-R132

It was made because AddLogger Ask timed out, throwing an AggregateException instead of an AskTimeoutException which was the exception that was expected.

Arkatufus · 2022-07-21T19:19:47Z

@Aaronontheweb
I've decided to change how loggers are loaded, all loggers are loaded asynchronously now. A warning will be emitted for each late responders if they didn't respond within the alloted timeout time.
The con with this approach is that the Ask task will be awaited forever for throwing logger actors, since we do not have a way to trap this inside LoggingBus, but this is basically what happens with the old implementation, a detached task with no timeout.

Arkatufus · 2022-07-21T19:23:59Z

src/core/Akka/Event/LoggingBus.cs

            foreach (var strLoggerType in loggerTypes)
            {
                var loggerType = Type.GetType(strLoggerType);
                if (loggerType == null)
                {
-                    throw new ConfigurationException($@"Logger specified in config cannot be found: ""{strLoggerType}""");
+                    Publish(new Error(null, logName, GetType(), $@"Logger specified in config cannot be found: ""{strLoggerType}"""));


We log an error instead of stopping the ActorSystem when a logger type can not be found

If you consider a logger to be critical infrastructure, isn't this a bad idea? i.e. if I don't have visibility into how my service runs at a basic level, how can I be sure it's working correctly?

I'd probably leave the old fail-fast mechanic in-place, which should be even rarer now with the changes in Akka.Hosting.

This is different than the logger taking too long to startup - nothing is necessarily wrong with the users' configuration in that case. But in this case, the user's config is 100% wrong and they must fix it. That's why throwing an error here is a good idea.

Alright, I'll bring the exception code back

Arkatufus · 2022-07-21T19:24:51Z

src/core/Akka/Event/LoggingBus.cs

+                AddLogger(system, loggerType, logName);
+            }
+
+            if (!Task.WaitAll(_startupState.Keys.ToArray(), timeout))


We will wait for all loggers to be ready here, limiting the time to the timeout period.
The pro of this is that, instead of waiting for a timeout period for each loggers, we only wait once for everything, all logger Ask operation are performed concurrently.

Arkatufus · 2022-07-21T19:26:10Z

src/core/Akka/Event/LoggingBus.cs

                    {
-                        throw new ConfigurationException($"Logger [{strLoggerType}] specified in config cannot be loaded: {ex}", ex);
+                        Publish(new Warning(logName, GetType(),


We log a warning if any of the Ask-ed loggers hasn't replied after the Wait

Arkatufus · 2022-07-21T19:27:10Z

src/core/Akka/Event/LoggingBus.cs

@@ -164,46 +173,68 @@ internal void StopDefaultLoggers(ActorSystem system)
                Publish(new Debug(SimpleName(this), GetType(), $"Shutting down: {Logging.SimpleName(system.Settings.StdoutLogger)} started"));
            }

+            // Cancel all pending logger initialization tasks
+            _shutdownCts.Cancel(false);


This is the mechanism to shutdown all pending Ask if they're still in progress even when the ActorSystem is shutting down.

Arkatufus · 2022-07-21T19:29:03Z

src/core/Akka/Event/LoggingBus.cs


+            _startupState[askTask] = new LoggerStartInfo(loggerName, loggerType, logger);
+            askTask.ContinueWith(t =>


We process all Ask result with a continuation here

Aaronontheweb

Has some issues

Aaronontheweb · 2022-07-22T12:25:33Z

src/core/Akka/Event/LoggingBus.cs

            foreach (var strLoggerType in loggerTypes)
            {
                var loggerType = Type.GetType(strLoggerType);
                if (loggerType == null)
                {
-                    throw new ConfigurationException($@"Logger specified in config cannot be found: ""{strLoggerType}""");
+                    Publish(new Error(null, logName, GetType(), $@"Logger specified in config cannot be found: ""{strLoggerType}"""));


If you consider a logger to be critical infrastructure, isn't this a bad idea? i.e. if I don't have visibility into how my service runs at a basic level, how can I be sure it's working correctly?

I'd probably leave the old fail-fast mechanic in-place, which should be even rarer now with the changes in Akka.Hosting.

Aaronontheweb · 2022-07-22T12:26:53Z

src/core/Akka/Event/LoggingBus.cs

+            _startupState[askTask] = new LoggerStartInfo(loggerName, loggerType, logger);
+            askTask.ContinueWith(t =>
+                {
+                    var info = _startupState[t];


Not safe to do this in a continuation, since this is now shared mutable state.

I'd keep the rest of the continuation but basically just purge the _startupState after the Task.WaitAll.

It should be safe since this is the only class where it is modified and there is no cross-pollination, each task handles its own continuation and have their own Task as their key.
We had to held on to _startupState because of the possibility that some loggers are not ready after the Task.WaitAll and they needed to retrieve their info. Would it be safe to use closure instead?

Removed the dictionary, changed it to closure. Just needed the logger name for logging purposes outside of the Task continuation

Aaronontheweb · 2022-07-22T12:30:50Z

src/core/Akka/Event/LoggingBus.cs

            foreach (var strLoggerType in loggerTypes)
            {
                var loggerType = Type.GetType(strLoggerType);
                if (loggerType == null)
                {
-                    throw new ConfigurationException($@"Logger specified in config cannot be found: ""{strLoggerType}""");
+                    Publish(new Error(null, logName, GetType(), $@"Logger specified in config cannot be found: ""{strLoggerType}"""));


This is different than the logger taking too long to startup - nothing is necessarily wrong with the users' configuration in that case. But in this case, the user's config is 100% wrong and they must fix it. That's why throwing an error here is a good idea.

Aaronontheweb

LGTM

Aaronontheweb · 2022-07-27T14:29:33Z

@Arkatufus needs a backport to v1.5

* Fix faulty AddLogger in LoggingBus * Ignore logger async start setting, not relevant anymore * Simplify unit test * Send Stop instead of PoisonPill * Make loggers load asynchronously by default * Change logging back to exceptions * Remove _startupState, use closure instead Co-authored-by: Aaron Stannard <aaron@petabridge.com> (cherry picked from commit c8b46b4)

Fix faulty AddLogger in LoggingBus

a5b01a9

Arkatufus commented Jul 1, 2022

View reviewed changes

src/core/Akka/Event/LoggingBus.cs Show resolved Hide resolved

Arkatufus commented Jul 1, 2022

View reviewed changes

src/core/Akka/Event/LoggingBus.cs Outdated Show resolved Hide resolved

Ignore logger async start setting, not relevant anymore

5fdae50

Arkatufus commented Jul 1, 2022

View reviewed changes

src/core/Akka/Event/LoggingBus.cs Show resolved Hide resolved

Simplify unit test

780b353

Aaronontheweb requested changes Jul 18, 2022

View reviewed changes

src/core/Akka/Event/LoggingBus.cs Outdated Show resolved Hide resolved

src/core/Akka/Event/LoggingBus.cs Show resolved Hide resolved

Send Stop instead of PoisonPill

15b4a77

Arkatufus requested a review from Aaronontheweb July 19, 2022 16:40

Arkatufus added 2 commits July 19, 2022 23:41

Merge branch 'v1.4' into 1.4/Fix_LoggingBus_AddLogger

390cb12

Make loggers load asynchronously by default

0bb4b97

Arkatufus commented Jul 21, 2022

View reviewed changes

Merge branch 'v1.4' into 1.4/Fix_LoggingBus_AddLogger

6727e63

Aaronontheweb requested changes Jul 22, 2022

View reviewed changes

Arkatufus added 3 commits July 22, 2022 22:38

Change logging back to exceptions

795a70e

Remove _startupState, use closure instead

c4621b0

Merge branch 'v1.4' into 1.4/Fix_LoggingBus_AddLogger

4a80b62

Aaronontheweb approved these changes Jul 27, 2022

View reviewed changes

Aaronontheweb added this to the 1.4.41 milestone Jul 27, 2022

Aaronontheweb added logging akka-actor labels Jul 27, 2022

Aaronontheweb merged commit c8b46b4 into akkadotnet:v1.4 Jul 27, 2022

Arkatufus mentioned this pull request Jul 28, 2022

[BACKPORT #6028] Fix faulty AddLogger in LoggingBus #6053

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix faulty AddLogger in LoggingBus #6028

Fix faulty AddLogger in LoggingBus #6028

Arkatufus commented Jul 1, 2022

Aaronontheweb left a comment

Aaronontheweb commented Jul 18, 2022

Arkatufus commented Jul 18, 2022

Arkatufus commented Jul 19, 2022

Arkatufus commented Jul 21, 2022

Arkatufus Jul 21, 2022

Aaronontheweb Jul 22, 2022

Aaronontheweb Jul 22, 2022

Arkatufus Jul 22, 2022

Arkatufus Jul 21, 2022 •

edited

Arkatufus Jul 21, 2022

Arkatufus Jul 21, 2022

Arkatufus Jul 21, 2022

Aaronontheweb left a comment

Aaronontheweb Jul 22, 2022

Aaronontheweb Jul 22, 2022

Aaronontheweb Jul 22, 2022

Arkatufus Jul 22, 2022

Arkatufus Jul 22, 2022

Aaronontheweb Jul 22, 2022

Aaronontheweb left a comment

Aaronontheweb commented Jul 27, 2022


		_startupState[askTask] = new LoggerStartInfo(loggerName, loggerType, logger);
		askTask.ContinueWith(t =>

Fix faulty AddLogger in LoggingBus #6028

Fix faulty AddLogger in LoggingBus #6028

Conversation

Arkatufus commented Jul 1, 2022

Aaronontheweb left a comment

Choose a reason for hiding this comment

Aaronontheweb commented Jul 18, 2022

Arkatufus commented Jul 18, 2022

Arkatufus commented Jul 19, 2022

Arkatufus commented Jul 21, 2022

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

Arkatufus Jul 21, 2022 • edited

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

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

Aaronontheweb commented Jul 27, 2022

Arkatufus Jul 21, 2022 •

edited