Custom logger shutdown order.

[djm132]

I am using Akka.NET 1.3.16 with NET Core 3.0 web server application and custom logger to reuse configured NLog. During ActorSystem.Terminate() sometimes logger actor stopped too early and unformatted logs printed using StandardOutLogger.

Expected behavior:
Logger actor should be stopped last during system termination.

Issue looks like

[Danthar]

I think this is an design issue. Loggers are created under the \System actor. So assuming you registered your custom logger in hocon like any other logger, it should run there as well.

This means this is a race condition between the system actor cleaning up its children and the rest of the system shutting down.
So yes this can happen. But i don't see an easy way of fixing this, short of making drastic changes to how logging actors are handled.
So i don't think this will be fixed.

[djm132]

This can be solved easily with introducing StandardOutLogger hook for printing log events. Added pr for this #4053.

[Danthar]

In my humble opinion. Thats not a fix. Thats a hack.
A fix would be that the logging actor subsystem is the very last actor to be shutdown, so that any log messages are routed through the logging actor till the very end. This way there isn't anything a user needs to do to prevent this scenario, it just works.

/cc @Aaronontheweb @Horusiath Opinions?

[djm132]

May be it makes sense to introduce some interface like

interface IShutdownOrder {
    int ShutdownOrder { get; }
}

and process childs sorted (with default to 0 if not present) ? Then we can make Logger order as int.MinValue.

[Aaronontheweb]

I agree with @Danthar and I closed the original PR.

/system actors are always shut down last, but the order in which those actors are terminated is arbitrary - it depends entirely on the dispatcher and the scheduler. However, the logging actors in Akka.NET get special treatment - they only get shutdown once the ActorSystem has finished running all of its termination hooks for cleaning up things like Akka.Remote connections and so on.

The StandardOutLogger gets started at the very end to capture any output from shutting down the other parts of the logging system as it shuts down, so it happens at the very, very end. There shouldn't be anything else important happening by this point as the rest of the application has already been terminated by the time the ActorSystem shutdown process reaches this point.

What's the business goal that you're trying to accomplish here?

[djm132]

The main reason was to wrap termination messages to our nlog or hide them at all. Is there any way to suppress this output ? Assuming that logging level already set to debug before start in hocon config.

[Aaronontheweb]

Ah, there might be a way to hide them via configuration - let me check that

[tometchy]

The StandardOutLogger gets started at the very end to capture any output from shutting down the other parts of the logging system as it shuts down, so it happens at the very, very end. There shouldn't be anything else important happening by this point as the rest of the application has already been terminated by the time the ActorSystem shutdown process reaches this point.

@Aaronontheweb In my case it's very unfortunate - I have created simple console app which gets invoked with commands then do it's job and quits - like Git, for example git status shows current status then quits app.

I designed it with Akka.Net - I know downsides of this decision, I know that every time I invoke app, whole actor system must be created and in my case it's acceptable performance, so this is not the subject to this comment (in the future I can move logic to separate long living process, like Docker does, invoking docker ps doesn't start up whole Docker, it just connects to deamon).

Of course I want logs, so I have configured NLog to save logs to file. But I never want them in console output, as this is my user interface, so I have explicitly configured stdout-loglevel = off

But with akka's design quoted in the beginning of this comment, every time job is done I see in my console output:

[DEBUG][2021-09-02 07:50:46][Thread 0009][EventStream] Shutting down: StandardOutLogger started
[DEBUG][2021-09-02 07:50:46][Thread 0009][EventStream] unsubscribing [akka://Q/system/log1-NLogLogger#918463714] from all channels

So to understand why I don't want this, imagine I that I now want to create new Git version rewritten with Akka.Net and every time user wants to see repo status sees something like this:

On branch master
Your branch is up to date with 'origin/master'.

nothing to commit, working tree clean
[DEBUG][2021-09-02 07:50:46][Thread 0009][EventStream] Shutting down: StandardOutLogger started
[DEBUG][2021-09-02 07:50:46][Thread 0009][EventStream] unsubscribing [akka://Q/system/log1-NLogLogger#918463714] from all channels

In my view (and this is what I asks for) this behavior should be changed and starts to respect stdout-loglevel log level (which can be set to off) or maybe some new configuration should be added, something like start-up-stdout-during-shutdown.

[Aaronontheweb]

Ok @tometchy - so in this case, is the ask here for us to go through and make sure that stdout-loglevel = off gets enforced all the way down top to bottom? Because that's doable.

[Aaronontheweb]

As for the original issue - the logger shutdown order, this might be doable with a custom CoordinatedShutdown stage these days. Loggers usually shut down at the very end of the process for obvious reasons, but it could be possible to customize this to a degree by changing the final stages of the termination process possibly.

[tometchy]

Ok @tometchy - so in this case, is the ask here for us to go through and make sure that stdout-loglevel = off gets enforced all the way down top to bottom? Because that's doable.

Yes, if it's off I don't want it to be up at any moment, thanks :)
But if someone likes this behavior, then maybe some extra configuration would suit's both cases.

[Aaronontheweb]

But if someone likes this behavior, then maybe some extra configuration would suit's both cases.

Nah, this is definitely a bug on our part. We should just fix it so off means off.

[Aaronontheweb]

Moved to issue #5246