When you write logs in an application, you likely have a dedicated class (or even a singleton instance) that handles the writing of these logs and that you use throughout your code. This mechanism is usually simple and straightforward. But if you take a look at how the logger is used in PandApache, you might be a bit surprised by this line:
ExecutionContext.Current.Logger.LogInfo($"Admin server listening on {ServerConfiguration.Instance.ServerIP}:{ServerConfiguration.Instance.AdminPort}");
Output:
12/09/2024 12:26:48 - Module: Admin - Thread ID: 1 - INFO - Admin server listening on 0.0.0.0:4040
Before explaining this line, let’s take a step back to understand how we got here.
How does PandApache work?
When PandApache is running, you have several elements in play:
- The Service: the main program itself.
- Modules: each module creates a new task, as they run concurrently.
- Subtasks: some modules may start their own subtasks depending on the action they are performing.
The goal is to make each module as independent and configurable as possible. Therefore, each module should have:
- Its own logger: this allows you to know which log was written by which module, while applying specific logging rules (different levels, different files, etc.).
- Its own task scheduler: so as not to monopolize all the resources and to leave enough for others.
How to manage the correct logger in each module?
There are several ways to ensure that each module uses the correct logger (and the correct task scheduler, but we’ll set that aside for now). One solution would be to pass the appropriate logger as a parameter to each method, or to use dependency injection. This could look like:
Logger loggerAdmin = new Logger(configAdmin);
Logger loggerWeb = new Logger(configWeb);
Module moduleAdmin = new Module(loggerAdmin);
Module moduleWeb = new Module(loggerWeb);
This approach is not ideal. Why? Because each sub-function would need to access the correct logger, either by passing it explicitly as a parameter or through dependency injection, which can quickly become cumbersome and redundant.
Let’s take an example in a module:
Module{
public Logger LoggerAdmin;
Foo() {
LoggerAdmin.LogInfo("Here");
RandomObject.Bar(LoggerAdmin);
}
}
RandomObject{
Bar(Logger logger) {
logger.LogInfo("There");
}
}
You could also opt for a solution with static objects that return the correct logger, which would give:
Foo() {
LoggerAdmin.LogInfo("Here");
}
Bar() {
LoggerAdmin.LogInfo("There");
}
But this solution has two major problems:
Manually choosing the correct logger: For every function or class, you have to decide which logger to use. And if a function changes context (for example, from the Web module to the Admin module), you constantly need to adapt this choice. This lacks flexibility and increases the risk of bugs.
Handling multiple instances: The Web and Admin modules are actually two instances of the same module, but running the same code. How do you ensure each instance has its own logger without specifying it in every call?
The real challenge is to find a way to automatically retrieve the correct logger (or any other module-specific object) without having to specify it each time and without using specific parameters. This object must be determined based on the module that is currently running, and not manually at each function call.
With that in mind, how could you solve this problem more elegantly? Leave a comment to share your approach and explain how you would handle dependency injection in this context, particularly for module-specific objects like the logger.
Virtual Logger
To fully understand the final solution, it's important to have the desired logs in mind. Here are the PandApache logs:
12/09/2024 12:33:25 - Module: Server - Thread ID: 1 - WARNING - Module Telemetry disabled
12/09/2024 12:33:25 - Module: Server - Thread ID: 1 - INFO - PandApache3 is starting
12/09/2024 12:33:25 - Module: Web - Thread ID: 1 - INFO - Starting Connection manager module
12/09/2024 12:33:25 - Module: Web - Thread ID: 1 - INFO - Web server listening on 0.0.0.0:8080
12/09/2024 12:33:25 - Module: Admin - Thread ID: 1 - INFO - Starting Connection manager module
12/09/2024 12:33:25 - Module: Admin - Thread ID: 1 - INFO - Admin server listening on 0.0.0.0:4040
12/09/2024 12:33:25 - Module: default - Thread ID: 1 - INFO - PandApache3 process id:3738
12/09/2024 12:33:25 - Module: default - Thread ID: 1 - INFO - PandApache3 process name:dotnet
12/09/2024 12:33:25 - Module: Server - Thread ID: 1 - INFO - PandApache3 is up and running!
12/09/2024 12:33:25 - Module: Web - Thread ID: 6 - INFO - Running Connection manager module
12/09/2024 12:33:28 - Module: Web - Thread ID: 6 - INFO - Client connected
12/09/2024 12:33:28 - Module: Web - Thread ID: 12 - INFO - Reading query string parameter
12/09/2024 12:33:28 - Module: Web - Thread ID: 13 - INFO - LoggerMiddleware invoked
12/09/2024 12:33:28 - Module: Web - Thread ID: 13 - INFO - Log Request
12/09/2024 12:33:28 - Module: Web - Thread ID: 13 - INFO - [12/09/2024 10:33:28] GET /
12/09/2024 12:33:28 - Module: Web - Thread ID: 14 - INFO - Log Response
12/09/2024 12:33:28 - Module: Web - Thread ID: 14 - INFO - [12/09/2024 10:33:28] Response status code: 200
12/09/2024 12:33:28 - Module: Web - Thread ID: 14 - INFO - client Closed
12/09/2024 12:33:28 - Module: Web - Thread ID: 6 - INFO - Client connected
12/09/2024 12:33:28 - Module: Web - Thread ID: 13 - INFO - Reading query string parameter
These logs show typical information, but two elements that change regularly and are very important are the module and thread ID.
To understand how we got to these logs, it's logical to first look at the components of a PandApache module, particularly its properties. Here are the properties of the ConnectionManager module, which is the class instantiated for both the Web and Admin modules:
public TcpListener Listener { get; set; }
public TaskFactory TaskFactory { get; }
public ModuleConfiguration ModuleInfo { get; set; }
public ModuleType ModuleType { get; set; }
private static AsyncLocal<ModuleConfiguration> _current = new AsyncLocal<ModuleConfiguration>();
public CancellationTokenSource _cancellationTokenSource { get; } = new CancellationTokenSource();
private ConcurrentDictionary<Guid, ISocketWrapper> _clients { get; } = new ConcurrentDictionary<Guid, ISocketWrapper>();
private ConcurrentDictionary<Guid, ISocketWrapper> _clientsRejected = new ConcurrentDictionary<Guid, ISocketWrapper>();
private Func<HttpContext, Task> _pipeline;
private TaskScheduler _taskScheduler;
The properties that will interest us are:
public ModuleConfiguration ModuleInfo { get; set; }private TaskScheduler _taskScheduler;
The TaskScheduler is quite simple, although we have re-implemented our own TaskScheduler for a few modifications. It's an inheritance of the default class, so it functions in a similar way.
The ModuleConfiguration, however, is an original class that looks like this:
public class ModuleConfiguration
{
private TaskScheduler _taskScheduler;
public ModuleType Type;
public string Name;
public bool isEnable;
public TaskFactory TaskFactory { get; }
public VirtualLogger Logger;
public ModuleConfiguration(string name)
{
Name = name;
Type = moduleType;
Logger = new VirtualLogger(name);
}
}
We can see the TaskScheduler again, but we also have a VirtualLogger that takes a name as a parameter.
A VirtualLogger behaves exactly like the normal PandApache logger. In fact, both the VirtualLogger and Logger classes implement the ILogger interface.
The difference is that the VirtualLogger sends its log to the Logger, and the Logger sends the log to the system (either the console or a file).
So, we have modules running in their own tasks, each containing the two instances of objects that we want to use in very specific execution contexts. We now have all the components in place for what we want to achieve. Let's see how this works.
Between us
One might say that a
VirtualLoggeris an unnecessary abstraction here. We could easily use the originalLoggerclass with different instances, just like we do with theVirtualLogger. This is true, but there are other benefits to using theVirtualLoggerthat haven't been explained here. What you need to take away is that theVirtualLoggeris not just there to have independent loggers, but primarily to separate the action of logging information and the action of distributing it, whether to the console or to a file. We’ll explore this in a future blog post.
Execution Context
Let’s revisit the line to execute the logger from earlier.
ExecutionContext.Current.Logger.LogInfo($"Admin server listening on {ServerConfiguration.Instance.ServerIP}:{ServerConfiguration.Instance.AdminPort}");
It’s time to talk about the ExecutionContext object. It’s a simple class that contains just a static field for easy access everywhere. Here it is:
public static class ExecutionContext
{
private static AsyncLocal<ModuleConfiguration> _current = new AsyncLocal<ModuleConfiguration>();
public static ModuleConfiguration Current
{
get => _current.Value;
set => _current.Value = value;
}
}
The special feature of this class is the type of _current, which is an AsyncLocal<ModuleConfiguration>. This ensures that _current has a distinct value across different execution contexts, meaning, across tasks.
Each module, at startup, assigns its ModuleInfo object to the _current field of its execution context:
ExecutionContext.Current = ModuleInfo;
When, within the module, the line:
ExecutionContext.Current.Logger.LogInfo("Starting Connection manager module");
Output:
12/09/2024 12:26:48 - Module: Web - Thread ID: 1 - INFO - Starting Connection manager module
is used, the correct logger for the module is indeed used.
Here are the two log outputs from the same line, generated by two modules (Web and Admin):
Output:
12/09/2024 12:26:48 - Module: Web - Thread ID: 1 - INFO - Starting Connection manager module
12/09/2024 12:26:48 - Module: Web - Thread ID: 1 - INFO - Web server listening on 0.0.0.0:8080
12/09/2024 12:26:48 - Module: Admin - Thread ID: 1 - INFO - Starting Connection manager module
12/09/2024 12:26:48 - Module: Admin - Thread ID: 1 - INFO - Admin server listening on 0.0.0.0:4040
When a module launches another task, like the Web module accepting a connection to process a request:
await AcceptConnectionsAsync(client);
We theoretically change context, as we are now in a sub-task of the main task. However, the value of the AsyncLocal property is automatically inherited, which means that in the AcceptConnectionsAsync function, when we use the logger via ExecutionContext:
ExecutionContext.Current.Logger.LogInfo($"Client connected");
Output:
12/09/2024 12:33:45 - Module: Admin - Thread ID: 9 - INFO - Client connected
We still have the correct ModuleInfo configured.
Finally
All of this allows us to do a lot within PandApache. For the loggers, even though each VirtualLogger differs very little (only the module name stored directly in the logger varies from one VirtualLogger to another), we still benefit from transparency and logical isolation when using them, as well as consistency and standardization when writing logs.
The TaskScheduler, which we’ve spoken little about because it’s less visual but functions exactly like the logger, once again allows us, in a very transparent way, to launch new tasks within our module. It enforces rules, especially regarding the number of custom threads. This ensures, for example, that the telemetry module, which is not a critical module, doesn’t consume too many resources (one thread for telemetry is sufficient, depending on the number of metrics you wish to capture).
On the other hand, if your web module no longer has enough resources to handle a new request, you’ll be quite frustrated. Ultimately, this shared execution context enables a finer resource management approach.
I hope this article helped you better understand the AsyncLocal in C#. If you’re interested in this language, know that the PandApache3 code is available on GitHub and live on Twitch. Feel free to follow the journey!
Top comments (0)