Quand vous écrivez des logs dans une application, vous avez sûrement une classe dédiée (voire une instance singleton) qui gère l’écriture de ces logs et que vous utilisez partout dans votre code. Ce mécanisme est généralement simple et direct. Mais si vous jetez un œil à la façon dont on utilise le logger dans PandApache, vous pourriez être un peu surpris par cette ligne :
ExecutionContext.Current.Logger.LogInfo($"Admin server listening on {ServerConfiguration.Instance.ServerIP}:{ServerConfiguration.Instance.AdminPort}");
Sortie:
12/09/2024 12:26:48 - Module: Admin - Thread ID: 1 - INFO - Admin server listening on 0.0.0.0:4040
Avant d'expliquer cette ligne, prenons un peu de recul pour comprendre comment on en est arrivé là.
Comment PandApache fonctionne?
Lorsque PandApache est en cours d'exécution, vous avez plusieurs éléments en jeu :
- Le Service : c'est le programme principal lui-même.
- Les modules : chaque module crée une nouvelle tâche, car ils s’exécutent simultanément.
- Les sous-tâches : certains modules peuvent démarrer leurs propres sous-tâches en fonction de l'action qu'ils effectuent.
L'objectif est de rendre chaque module le plus indépendant et configurable possible. Ainsi, chaque module doit posséder :
- Son propre logger : cela permet de savoir quel log a été écrit par quel module, tout en appliquant des règles de log spécifiques (niveaux différents, fichiers différents, etc.).
- Son propre task scheduler : pour ne pas monopoliser toutes les ressources et laisser suffisamment pour les autres
comment gérer le bon logger dans chaque module ?
Il existe plusieurs façons de s'assurer que chaque module utilise le bon logger (et le bon task scheduler, mais on va le laisser de coté pour le moment). Une solution serait de passer le logger approprié en paramètre à chaque méthode, ou d'utiliser l'injection de dépendance. Cela pourrait ressembler à ceci :
Logger loggerAdmin = new Logger(configAdmin);
Logger loggerWeb = new Logger(configWeb);
Module moduleAdmin = new Module(loggerAdmin);
Module moduleWeb = new Module(loggerWeb);
Cette approche n'est pas idéale. Pourquoi ? Parce qu'il faudrait que chaque sous-fonction puisse accéder au logger approprié, soit en le passant explicitement en paramètre, soit par injection de dépendance, ce qui peut rapidement devenir lourd et redondant.
Prenons un exemple dans un module :
Module{
public Logger LoggerAdmin;
Foo() {
LoggerAdmin.LogInfo("Here");
RandomObject.Bar(LoggerAdmin);
}
}
RandomObject{
Bar(Logger logger) {
logger.LogInfo("There");
}
}
On pourrait aussi opter pour une solution avec des objets statiques qui renverraient le bon logger, ce qui donnerait :
Foo() {
LoggerAdmin.LogInfo("Here");
}
Bar() {
LoggerAdmin.LogInfo("There");
}
Mais cette solution présente deux problèmes majeurs :
Choisir manuellement le bon logger : À chaque fonction ou classe, il faut décider quel logger utiliser. Et si une fonction change de contexte (par exemple, du module Web au module Admin), il faut constamment adapter ce choix. Cela manque de flexibilité et augmente les risques de bugs.
La gestion des instances multiples : Les modules Web et Admin sont en réalité deux instances du même module, mais qui exécutent le même code. Comment faire en sorte que chaque instance ait son propre logger sans avoir à le spécifier à chaque appel ?
Le véritable défi est de trouver un moyen de récupérer automatiquement le bon logger (ou tout autre objet spécifique au module) sans avoir à le préciser chaque fois et sans passer par des paramètres spécifiques. Ce bon objet doit être déterminé en fonction du module qui est actuellement en cours d’exécution, et non de manière manuelle à chaque appel de fonction.
Dans cette optique, comment pourriez-vous résoudre ce problème de manière plus élégante ? Laissez un commentaire pour partager votre approche et expliquer comment vous géreriez l’injection de dépendances dans ce contexte, en particulier pour des objets spécifiques à chaque module comme le logger.
Virtual Logger
Pour bien imaginer la solution finale, avoir les logs souhaités en tête est important. Voici les logs de PandApache :
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
On y voit des informations classiques, mais deux éléments qui changent de façon régulière et qui sont très importants : le module et le thread ID.
Pour comprendre comment on en arrive à ces logs, le plus logique est sans doute de commencer par regarder de quoi est composé un module de PandApache, notamment ses propriétés. Voici les propriétés du module ConnectionManager, qui est la classe instanciée pour le module Web et Admin :
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;
Les propriétés qui vont nous intéresser en particulier sont :
public ModuleConfiguration ModuleInfo { get; set; }private TaskScheduler _taskScheduler;
Le TaskScheduler est plutôt simple, même si nous avons réimplémenté notre propre TaskScheduler pour quelques modifications. C’est un héritage de la classe par défaut et donc fonctionne globalement de la même manière.
ModuleConfiguration, quant à elle, est une classe originale que voici :
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);
}
}
On retrouve notre TaskScheduler, mais nous avons aussi un VirtualLogger qui prend en paramètre un nom.
Un VirtualLogger est exactement comme le logger normal de PandApache. D’ailleurs, la classe VirtualLogger et Logger implémentent tous deux l’interface ILogger.
La différence est que le VirtualLogger envoie son log au Logger, et ce dernier envoie son log au système (Console ou fichier).
Nous avons donc des modules qui s’exécutent chacun dans leur propre tâche et qui contiennent nos deux instances d’objets que l’on souhaite utiliser dans des contextes d’exécution bien précis. Nous avons tous les éléments mis en place pour ce que nous souhaitons faire, il suffit de voir ensemble comment cela fonctionne.
Entre nous
On pourrait se dire qu’un
VirtualLoggerest une abstraction inutile ici. On pourrait très bien utiliser directement la classeLoggeroriginelle avec plusieurs instances différentes, exactement comme ce que l’on fait avec leVirtualLogger. C’est certes vrai, mais il y a d'autres avantages auVirtualLoggerqui n’ont pas été expliqués ici. Ce qu’il faut retenir, c’est que leVirtualLoggern’est pas là uniquement pour avoir des loggers indépendants, mais surtout pour séparer l’action de logger une information et l’action de la distribuer, que ce soit à la console ou dans un fichier. On explorera cela dans un prochain billet de blog.
Le Contexte d'Exécution
Reprenons la ligne pour exécuter le logger du début.
ExecutionContext.Current.Logger.LogInfo($"Admin server listening on {ServerConfiguration.Instance.ServerIP}:{ServerConfiguration.Instance.AdminPort}");
Il est temps de parler de l’objet ExecutionContext. Il s’agit d’une classe simple qui ne contient qu’un champ statique pour être appelé de partout facilement. La voici :
public static class ExecutionContext
{
private static AsyncLocal<ModuleConfiguration> _current = new AsyncLocal<ModuleConfiguration>();
public static ModuleConfiguration Current
{
get => _current.Value;
set => _current.Value = value;
}
}
La particularité de cette classe est le type de _current, qui est un AsyncLocal<ModuleConfiguration>. Cela nous permet de garantir une valeur distincte de _current dans les différents contextes d'exécution, autrement dit, dans les tâches.
Chaque module, au démarrage, assigne à la variable _current de son contexte d'exécution l’objet ModuleInfo :
ExecutionContext.Current = ModuleInfo;
Quand, dans le module, la ligne :
ExecutionContext.Current.Logger.LogInfo("Starting Connection manager module");
Sortie:
12/09/2024 12:26:48 - Module: Web - Thread ID: 1 - INFO - Starting Connection manager module
est utilisée, c’est donc bien le bon logger qui est utilisé, celui du module.
D'ailleurs voici les 2 sorties de log de cette même ligne généré par 2 modules (Web et Admin)
Sortie:
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
Quand un module lance une autre tâche, comme le module Web qui accepte une connexion pour traiter la requête :
await AcceptConnectionsAsync(client);
On change théoriquement de contexte, on est dans une sous-tâche de la tâche principale. Cependant, la valeur de la propriété AsyncLocal est automatiquement héritée, ce qui fait que dans la fonction AcceptConnectionsAsync, quand on utilise le logger via ExecutionContext :
ExecutionContext.Current.Logger.LogInfo($"Client connected");
sortie:
12/09/2024 12:33:45 - Module: Admin - Thread ID: 9 - INFO - Client connected
Nous avons toujours le bon ModuleInfo configuré.
Finalement
Tout ceci nous permet beaucoup de choses dans PandApache. Pour les loggers, même si chaque VirtualLogger diffère très peu (seul le nom du module stocké directement dans le logger diffère d’un VirtualLogger à l’autre), nous avons quand même l’avantage de la transparence et de l’isolation logique au moment de l’utilisation, ainsi que de la cohérence et de la standardisation au moment de l’écriture.
Le TaskScheduler, dont nous avons très peu parlé car moins visuel, mais qui fonctionne exactement comme le logger, nous permet encore une fois de façon très transparente de lancer de nouvelles tâches dans notre module, en ayant des règles notamment au niveau du nombre de threads personnalisés. Ainsi, on peut s’assurer que le module télémetrie, qui n’est pas un module vital, n’utilise pas trop de ressources (un thread pour la télémetrie est, par exemple, suffisant selon le nombre de métriques que vous souhaitez capturer).
Au contraire, si votre module web n’a plus assez de ressources pour gérer une nouvelle requête, vous allez être très contrarié. C’est donc une gestion des ressources plus fine qui peut être effectuée au final grâce à ce contexte d’exécution partagé.
J’espère que cet article vous aura aidé à mieux comprendre l'utilisation de AsyncLocal en C#. Si ce langage vous intéresse, sachez que le code de PandApache3 est disponible sur GitHub et en live sur Twitch. N’hésitez pas à suivre l’aventure !
Top comments (0)