Akka.net: Attempted to divide by zero

[diegolinan]

So, I'm trying to use Akka on Xamarin on my macbook. I am using the .Net framework 4.6.1 and I'm getting this nice error when trying to create a new actor system:

[ERROR][12/31/2016 9:12:32 PM][Thread 0005][akka://UserProfileActorSystem/system/log1-DefaultLogger] Attempted to divide by zero.
Cause: System.DivideByZeroException: Attempted to divide by zero.
  at System.TermInfoDriver.ChangeColor (System.String format, System.ConsoleColor color) [0x00016] in /private/tmp/source-mono-4.6.0/bockbuild-mono-4.6.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System/TermInfoDriver.cs:398 
  at System.TermInfoDriver.set_ForegroundColor (System.ConsoleColor value) [0x00011] in /private/tmp/source-mono-4.6.0/bockbuild-mono-4.6.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System/TermInfoDriver.cs:432 
  at System.ConsoleDriver.set_ForegroundColor (System.ConsoleColor value) [0x0001f] in /private/tmp/source-mono-4.6.0/bockbuild-mono-4.6.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System/ConsoleDriver.cs:134 
  at System.Console.set_ForegroundColor (System.ConsoleColor value) [0x00000] in /private/tmp/source-mono-4.6.0/bockbuild-mono-4.6.0-branch/profiles/mono-mac-xamarin/build-root/mono-x86/mcs/class/corlib/System/Console.cs:587 
  at Akka.Util.StandardOutWriter.WriteToConsole (System.String message, System.Nullable`1[T] foregroundColor, System.Nullable`1[T] backgroundColor, System.Boolean line) [0x00034] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Util.StandardOutWriter.WriteLine (System.String message, System.Nullable`1[T] foregroundColor, System.Nullable`1[T] backgroundColor) [0x00000] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Event.StandardOutLogger.PrintLogEvent (Akka.Event.LogEvent logEvent) [0x0006a] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Event.DefaultLogger.Print (Akka.Event.LogEvent logEvent) [0x00000] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Event.DefaultLogger.Receive (System.Object message) [0x00026] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Actor.ActorBase.AroundReceive (Akka.Actor.Receive receive, System.Object message) [0x00000] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Actor.ActorCell.ReceiveMessage (System.Object message) [0x00011] in <9e39de83b9544f988b2007a135264702>:0 
  at Akka.Actor.ActorCell.Invoke (Akka.Actor.Envelope envelope) [0x00057] in <9e39de83b9544f988b2007a135264702>:0 

My code so far is pretty straightforward and not complex at all:

    class MainClass
    {
        private static ActorSystem AnActorSystem;

        public static void Main(string[] args)
        {
            AnActorSystem = ActorSystem.Create("AnActorSystem");

            Console.ReadLine();

            UserProfileActorSystem.Terminate();
        }
    }

Any ideas?

[to11mtm]

Some notes based on poking around; Looks like the specific problem is when mono internals try to do a modulo against 'maxColors'. That number appears to be read from a .h file on the system to determine capabilities per https://github.com/mono/mono/blob/master/mcs/class/corlib/System/TermInfoReader.cs#L70 , or alternatively from a location specified in an environment variable: https://github.com/mono/mono/blob/master/mcs/class/corlib/System/TermInfoDriver.cs#L122

If none of those are present, it tries to go to a fallbacks (xterm if in use, linux if in use, finally ANSI), which might not have the info needed in this case.

That said, I don't have the gear to test any of this handy, but perhaps that file requires some defining on the machine in question?

[diegolinan]

Well... I don't think I have the time or will to fix that right now... But I'll give it a shot later on. For now the, I'm stuck using AKKA on windows... Thanks a lot!

[Horusiath]

Since this issue looks like it's oriented around custom console logger, the easiest workaround would be to replace it with the custom one (i.e. NLog or Serilog).

[diegolinan]

That could be a nice workaround... Will try it and let you know

[Danthar]

@Horusiath Its not a custom console logger. Its the default consolelogger.

[diegolinan]

It is definitely the console logger which Akka.NET uses as it's default logging method (for what I understand) So, what @Horusiath proposes, for now, could solve my issue. Maybe implement NLog to override the default console logger might do the trick. As soon as I get back to my Mac I will try that, but a fix would be greatly appreciated (-:

[diegolinan]

Apparently, adding the HOCON configuration with the flag

akka { actor.debug.unhandled = on loglevel = DEBUG }

for some reason unknown, made it work...

[nagytech]

Some notes based on poking around; Looks like the specific problem is when mono internals try to do a modulo against 'maxColors'. That number appears to be read from a .h file on the system to determine capabilities per https://github.com/mono/mono/blob/master/mcs/class/corlib/System/TermInfoReader.cs#L70 , or alternatively from a location specified in an environment variable: https://github.com/mono/mono/blob/master/mcs/class/corlib/System/TermInfoDriver.cs#L122

The code linked above may have been valid at the time of posting, but it is linked to master branch with likely has changed since then. As identified by the logs in the initial post, the target version was mono-4.6.0-branch. For convenience, I've linked the correctly versioned class and the line of exception below:

https://github.com/mono/mono/blob/cf24b9f9d4b80512122f998a47cae850df1d4cb2/mcs/class/corlib/System/TermInfoDriver.cs#L398

As stated earlier in the thread, it is correct that the issue occurs during a call to ChangeColor where the modulo is calculated. And this only occurs when maxColors has a value of 0 which is the default state which exists before Init is called.

After Init is called, maxColors is assigned the result of Math.Max(..., 1) meaning it's impossible for the value of maxColors to be less than 1 - even if the code can't find a setting for the current system.

    maxColors = reader.Get (TermInfoNumbers.MaxColors);
    maxColors = Math.Max (Math.Min (maxColors, 16), 1);

So, I think the root cause of the issue is that ChangeColor is called before Init, or a deadlock / exception is thrown (not caught) before Init can assign a non-zero value to maxColors - the former case being more likely. And, since ChangeColor is implicitly private the only place it can be invoked is via setters on BackgroundColor and ForegroundColor properties.

I'll look into the Akka code and see if I can find any way we can defer the call to the Back/ForegroundColor properties to give Init a chance to complete execution.

[nagytech]

I just realised the property setters will always call Init where it is necessary to do so.

The problem is then as follows:

• For every property call to change Back/Foreground Colors
• The value of inited is checked and where inited is false, Init is called
• Inside Init, the value of inited is checked twice and will return if the value is false
• Then, inited is set to true before any initialisation code is even run

So, the fact that inited is set to true before maxColors is set means that any other concurrent threads will be accessing a state that has not been properly inited.

I'm confident that this issue should be resolved in Mono by utilising a more robust locking mechanism. Also, there may be something we can do in Akka to mitigate the problem until that time.

[nagytech]

The following code reproduces the issue which occurs as I explained previously. And, if the commented out line is activated, then the problem goes away because it gives Mono time to initialise the Console.

// var y = Console.BackgroundColor;
Parallel.Invoke(
    () => { var x = Console.ForegroundColor; },
    () => 
    {
        Console.BackgroundColor = ConsoleColor.Black;
        Console.WriteLine("writing!");
    }
);

I've traced the exception in Akka.NET to the Start method in ActorSystemImpl when it attempts to warn via WarnIfJsonIsDefaultSerializer. Additionally, if that log is suppressed, we can still trigger the issue via _settings.LogConfigOnStart.

[nagytech]

Coming back to this one after a bit of a break.

It looks like the call to Console.ReadLine() after the actor system is created is responsible for the racy behaviour. Easy to trigger under the following conditions:

• run in an environment that forces a NewtonSoftJsonSerializer warning
• enable logging of config on startup via log-config-on-start

In both the above cases, there is contention between the Console.ReadLine() (which causes the initialisation) and the StandardOutWriter's attempt to change the background colour during a partially initialised TermInfoDriver.

[Aaronontheweb]

closed via #4133