Akka .NET supports a flexible logging mechanism that can adapt with various logging providers, as we have seen in my earlier article on logging with Akka .NET. Aside from the default logger that writes to the console, you can plug in various loggers of your own choosing (e.g. NLog), set them up in configuration, and work with them using a common interface.
Sometimes, you may have specific logging requirements that are not covered by any of the existing logging plugins for Akka .NET. In such cases, you would need to write your own custom logger. Unfortunately, the Akka .NET Logging documentation does not explain how to do this at the time of writing this article.
This article is intended to fill this gap, explaining how to write a custom logger for Akka .NET, but also touching upon various topics such as reading custom configuration, actor lifecycle hooks, and cleanup of resources used by the ActorSystem. The source code for this article is available at the Gigi Labs BitBucket repository.
In a Nutshell
Akka .NET Logging is basically a port of Akka logging. Any logger is an actor that receives the following messages: Debug, Info, Warning, Error and InitializeLogger. These are all standard Akka .NET messages, and we will see how to use them in a minute. At the time of writing this article, I’ve come across the following loggers that one can refer to in order to see how custom loggers are built:
Main Program
For the sake of this article, we can go along with the following simple program:
using (var actorSystem = ActorSystem.Create("MyActorSystem"))
{
var logger = Logging.GetLogger(actorSystem, actorSystem, null);
logger.Info("ActorSystem created!");
Console.WriteLine("Press ENTER to exit...");
Console.ReadLine();
}
In my earlier Akka .NET logging article, we had done logging only from within actors. The above code shows how you can use the same configured logger directly from the ActorSystem.
We are now going to need a little configuration.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<configSections>
<section name="akka" type="Akka.Configuration.Hocon.AkkaConfigurationSection, Akka" />
</configSections>
<startup>
<supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.6.1" />
</startup>
<akka>
<hocon>
<![CDATA[ akka { loglevel = DEBUG loggers = ["AkkaNetCustomLogger.Loggers.ConsoleLogger, AkkaNetCustomLogger"] actor { debug { receive = on # log any received message autoreceive = on # log automatically received messages, e.g. PoisonPill lifecycle = on # log actor lifecycle changes event-stream = on # log subscription changes for Akka.NET event stream unhandled = on # log unhandled messages sent to actors } } } ]]>
</hocon>
</akka>
</configuration>
Here, we’re turning on all internal Akka .NET logging so that we can automatically get some logging output.
The important thing here is the loggers configuration, where we’re specifying the custom logger that we want Akka .NET to use. This is exactly how we had set up Akka .NET to use NLog in my earlier article, but this time we’re going to use a class called ConsoleLogger (which we have yet to create).
Writing the ConsoleLogger
As I mentioned earlier, any custom logger needs to handle five messages: Debug, Info, Warning, Error, and InitializeLogger. That’s the first thing we’ll set up our ConsoleLogger to do.
public class ConsoleLogger : ReceiveActor
{
public ConsoleLogger()
{
Receive<Debug>(e => this.Log(LogLevel.DebugLevel, e.ToString()));
Receive<Info>(e => this.Log(LogLevel.InfoLevel, e.ToString()));
Receive<Warning>(e => this.Log(LogLevel.WarningLevel, e.ToString()));
Receive<Error>(e => this.Log(LogLevel.ErrorLevel, e.ToString()));
Receive<InitializeLogger>(_ => this.Init(Sender));
}
// ...
}
The actual logging messages will use a common Log() helper method, since they differ only in log level (the operation of writing to the log destination is the same for all). Note that when we convert each of these classes to string, that includes the log level, so we don’t need to write it separately. In the case of the ConsoleLogger, we are passing in the LogLevel merely so we can use a different colour for each level.
The special message we haven’t covered yet is InitializeLogger. When the ActorSystem creates the logger actor, the internal event bus needs to know whether the logger is ready to start accepting messages. It does this by sending the logger actor an InitializeLogger message, and expects a LoggerInitialized message in return:
private void Init(IActorRef sender)
{
using (var consoleColour = new ScopedConsoleColour(ConsoleColor.Green))
Console.WriteLine("Init");
sender.Tell(new LoggerInitialized());
}
Aside from sending back the required message, I’m also logging the init operation itself, so that we can later observe the sequence of events. I am using my trusty ScopedConsoleColour class to change the colour, and then reset it back after the message has been written.
If you don’t send the LoggerInitialized message back, the actor system reports a timeout from initialising the logger, and basically you get no logging. (Well, ironically, the timeout itself is logged… presumably using the DefaultLogger as a fallback.)
Now we can implement our Log() helper method:
private void Log(LogLevel level, string message)
{
ConsoleColor colour = ConsoleColor.Gray;
switch (level)
{
case LogLevel.DebugLevel:
colour = ConsoleColor.Gray;
break;
case LogLevel.InfoLevel:
colour = ConsoleColor.White;
break;
case LogLevel.WarningLevel:
colour = ConsoleColor.Yellow;
break;
case LogLevel.ErrorLevel:
colour = ConsoleColor.Red;
break;
default: // shouldn't happen
goto case LogLevel.InfoLevel;
}
using (var consoleColour = new ScopedConsoleColour(colour))
Console.WriteLine(message);
}
Here we’re doing nothing but using a different colour per level, and writing the message to the console (which is pretty much what StandardOutLogger does). Remember, the level is already part of the message, so we don’t need to format it into the output message. (And if you’re outraged at the use of goto above, I suggest you read about goto case in C#.)
Actor Life Cycle Hooks
If your custom logger depends on external resources (which is most likely the case) such as the filesystem or a database, you will want to initialise those resources when the logger actor is created, and clean them up when it is destroyed. That work typically goes into actor life cycle hooks, i.e. overridable methods that allow you to run arbitrary code when an actor starts, stops, or restarts.
We don’t need to do this for ConsoleLogger, so we will simply log the start and stop operation instead. However, we will use these hooks more realistically when we implement the FileLogger.
protected override void PreStart()
{
base.PreStart();
using (var consoleColour = new ScopedConsoleColour(ConsoleColor.Green))
Console.WriteLine("PreStart");
}
protected override void PostStop()
{
using (var consoleColour = new ScopedConsoleColour(ConsoleColor.Green))
Console.WriteLine("PostStop");
base.PostStop();
}
We can now run this and see the logging in action:
Now, for something interesting, put a breakpoint inside PostStop(), and press ENTER to cause the program to continue and terminate. One would expect PostStop() to run as the ActorSystem is shutting down. But in fact, it doesn’t.
Next, go back to the main program, and add a second Console.ReadLine() at the end:
using (var actorSystem = ActorSystem.Create("MyActorSystem"))
{
var logger = Logging.GetLogger(actorSystem, actorSystem, null);
logger.Info("ActorSystem created!");
Console.WriteLine("Press ENTER to exit...");
Console.ReadLine();
}
Console.ReadLine();
Run it again, and when you press ENTER, the breakpoint is hit and the PostStop event is written to the console while waiting for the second ENTER:
When we disposed the ActorSystem earlier, the program terminated before the ActorSystem had the chance to do its cleanup work. It appears that when the ActorSystem shuts down, it doesn’t clean resources right away; most likely it is done using asynchronous messaging just like in the rest of Akka .NET. For this reason, in your program’s stopping code, you might want to wait a little bit between destroying the ActorSystem and actually letting the application terminate, in order to let it gracefully free its resources.
Writing the FileLogger
We will now write a second custom logger, this time one that writes to file.
First, change the HOCON configuration to use the new logger.
loggers = ["AkkaNetCustomLogger.Loggers.FileLogger, AkkaNetCustomLogger"]
Next, let’s write the FileLogger. As with the ConsoleLogger, we need to handle the same five messages:
public class FileLogger : ReceiveActor
{
private StreamWriter writer;
public FileLogger()
{
ReceiveAsync<Debug>(async e => await this.LogAsync(e.ToString()));
ReceiveAsync<Info>(async e => await this.LogAsync(e.ToString()));
ReceiveAsync<Warning>(async e => await this.LogAsync(e.ToString()));
ReceiveAsync<Error>(async e => await this.LogAsync(e.ToString()));
Receive<InitializeLogger>(_ => Sender.Tell(new LoggerInitialized()));
}
// ...
}
The logger keeps a reference to a StreamWriter, which wraps the file we will be writing to.
The LogAsync() method simply dumps the messages into that StreamWriter (remember, streams and toilets must always be flushed):
private async Task LogAsync(string message)
{
await this.writer.WriteLineAsync(message);
await this.writer.FlushAsync();
}
We can open the file itself either during the InitializeLogger handler or in PreStart(). Let’s use a fixed filename for now:
protected override void PreStart()
{
base.PreStart();
string filePath = "log.txt";
var fileStream = File.OpenWrite(filePath);
this.writer = new StreamWriter(fileStream);
}
We can then do the cleanup in PostStop():
protected override void PostStop()
{
// dispose the StreamWriter, and implicitly the
// underlying FileStream with it
this.writer.Dispose();
base.PostStop();
}
We only need to Dispose() our StreamWriter; doing that will automatically also close the underlying FileStream.
Now, while this is enough to log to file, there is a problem. We can’t actually use another program to read the log file while the program is running:
We can fix this by changing the way we open the file.
protected override void PreStart()
{
base.PreStart();
string filePath = "log.txt";
var fileStream = File.Open(filePath, FileMode.Append, FileAccess.Write, FileShare.Read);
this.writer = new StreamWriter(fileStream);
}
You’ll see that the log messages are now written to file:
However, there is another problem. If you press ENTER to close the program, the following happens:
Upon further inspection, it seems that logging messages are coming in around the same time that PostStop() is running, causing a race condition on the underlying resource. I’ve opened a bug report for this, but until this is sorted, you can flush synchronously as a workaround:
private async Task LogAsync(string message)
{
await this.writer.WriteLineAsync(message);
this.writer.Flush();
}
So, if there is this problem, how do existing logging adapters that have a file-based component (e.g. NLog) do their cleanup? Well, I’ve checked a few, and it seems they don’t.
Loading Custom Configuration
We’ve managed to write a file logger, but we’re using a fixed filename. How can we make it configurable?
It turns out we can just add an arbitrary setting anywhere in the HOCON configuration, and read it from inside the actor. So, let’s add this:
akka
{
loglevel = DEBUG
loggers = ["AkkaNetCustomLogger.Loggers.FileLogger, AkkaNetCustomLogger"]
logfilepath = "logfile.txt"
We can get to the setting we want using the configuration system in Akka .NET:
protected override void PreStart()
{
base.PreStart();
string filePath = "log.txt";
filePath = Context.System.Settings.Config
.GetString("akka.logfilepath", filePath);
var fileStream = File.Open(filePath, FileMode.Append, FileAccess.Write, FileShare.Read);
this.writer = new StreamWriter(fileStream);
}
Basically we’re reading the “akka.logfilepath” key from the HOCON config. We’re also passing in filePath as a default in case the setting is not found.
Running Multiple Loggers
So far we’ve been using either one logger or the other. But if you notice, the loggers configuration in HOCON is actually an array. Thus there is nothing stopping us from using multiple loggers at once:
akka
{
loglevel = DEBUG
loggers = ["AkkaNetCustomLogger.Loggers.FileLogger, AkkaNetCustomLogger",
"AkkaNetCustomLogger.Loggers.ConsoleLogger, AkkaNetCustomLogger"]
logfilepath = "logfile.txt"
Yes, it works:
