feat: add more logging and refactor middleware

Author: azhe403

ZiziBot.TelegramBot.Framework/Extensions/ClientExtension.cs

@@ -3,6 +3,7 @@
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 using ZiziBot.TelegramBot.Framework.Engines;
 using ZiziBot.TelegramBot.Framework.Handlers;
 using ZiziBot.TelegramBot.Framework.Interfaces;
@@ -43,6 +44,7 @@ public static IServiceCollection AddZiziBotTelegramBot(this IServiceCollection s
         using var provider = services.BuildServiceProvider();
 
         var hostingEnvironment = provider.GetRequiredService<IWebHostEnvironment>();
+        var logger = provider.GetRequiredService<ILogger<BotEngineHandler>>();
 
         var internalEngineConfig = new BotEngineConfig();
 
@@ -51,8 +53,8 @@ public static IServiceCollection AddZiziBotTelegramBot(this IServiceCollection s
             var botConfigurations = new List<BotTokenConfig>();
             var configuration = provider.GetRequiredService<IConfiguration>();
 
-            configuration.GetSection(BotTokenConfig.CONFIG_PATH).Bind(botConfigurations);
-            configuration.GetSection(BotEngineConfig.CONFIG_PATH).Bind(internalEngineConfig);
+            configuration.GetSection(BotTokenConfig.ConfigPath).Bind(botConfigurations);
+            configuration.GetSection(BotEngineConfig.ConfigPath).Bind(internalEngineConfig);
 
             services.AddSingleton(botConfigurations);
         }
@@ -64,6 +66,8 @@ public static IServiceCollection AddZiziBotTelegramBot(this IServiceCollection s
             internalEngineConfig = engineConfig;
         }
 
+        logger.LogInformation("Bot engine mode is {EngineMode}", internalEngineConfig.EngineMode);
+
 
         switch (internalEngineConfig.EngineMode)
         {
@@ -80,11 +84,13 @@ public static IServiceCollection AddZiziBotTelegramBot(this IServiceCollection s
             {
                 if (hostingEnvironment.IsDevelopment())
                 {
+                    logger.LogInformation("Starting bot in Polling mode because of Development environment");
                     services.EnablePollingEngine();
                     internalEngineConfig.ActualEngineMode = BotEngineMode.Polling;
                 }
                 else
                 {
+                    logger.LogInformation("Starting bot in Webhook mode because of non-Development environment");
                     services.EnableWebhookEngine();
                     internalEngineConfig.ActualEngineMode = BotEngineMode.Webhook;
                 }
@@ -103,13 +109,21 @@ public static IServiceCollection AddZiziBotTelegramBot(this IServiceCollection s
 
     private static IServiceCollection EnablePollingEngine(this IServiceCollection services)
     {
+        using var provider = services.BuildServiceProvider();
+        var logger = provider.GetRequiredService<ILogger<BotPollingEngine>>();
+
+        logger.LogInformation("Enabling Polling engine");
         services.AddSingleton<IBotEngine, BotPollingEngine>();
 
         return services;
     }
 
     private static IServiceCollection EnableWebhookEngine(this IServiceCollection services)
     {
+        using var provider = services.BuildServiceProvider();
+        var logger = provider.GetRequiredService<ILogger<BotWebhookEngine>>();
+
+        logger.LogInformation("Enabling Webhook engine");
         services.AddSingleton<IBotEngine, BotWebhookEngine>();
 
         return services;
@@ -127,7 +141,9 @@ public static async Task<IApplicationBuilder> UseZiziBotTelegramBot(this IApplic
     private static async Task<IApplicationBuilder> StartTelegramBot(this IApplicationBuilder app)
     {
         var botEngine = app.ApplicationServices.GetRequiredService<IBotEngine>();
+        var logger = app.ApplicationServices.GetRequiredService<ILogger<IBotEngine>>();
 
+        logger.LogInformation("Starting bot engine");
         await botEngine.Start();
 
         return app;

ZiziBot.TelegramBot.Framework/Handlers/BotUpdateHandler.cs

@@ -23,8 +23,8 @@ BotEngineConfig botEngineConfig
 {
     private IEnumerable<Type> BotCommands => GetCommands();
     private List<MethodInfo> BotMethods => GetMethods();
-
-    #region Invocation
+    
+    #region Type Handling
 
     public async Task<object?> HandleUpdate(ITelegramBotClient botClient, Update update, CancellationToken token)
     {
@@ -63,6 +63,7 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
     {
         try
         {
+            logger.LogTrace("Finding command for update type: {UpdateType}", update.Type);
             var method = update.Type switch
             {
                 UpdateType.InlineQuery => GetMethod(update.InlineQuery!),
@@ -76,6 +77,8 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
                 return null;
             }
 
+            logger.LogTrace("Found command for update type: {UpdateType}", update.Type);
+
             method.Update = update;
             var invokeMethod = await InvokeMethod(botClient, method);
 
@@ -94,6 +97,7 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
         try
         {
             var message = update.Message ?? update.EditedMessage;
+            logger.LogTrace("Finding command for message: {MessageText}", message?.Text);
             var method = GetMethod(message!);
 
             if (method == null)
@@ -102,6 +106,8 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
                 return null;
             }
 
+            logger.LogTrace("Found command for message: {MessageText}", message?.Text);
+
             method.Update = update;
 
             var invokeMethod = await InvokeMethod(botClient, method);
@@ -116,6 +122,10 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
         return null;
     }
 
+    #endregion
+
+    #region Invocation
+
     private async Task<object?> InvokeMethod(ITelegramBotClient client, BotCommandInfo? botCommandInfo)
     {
         if (botCommandInfo is null)
@@ -140,15 +150,38 @@ private async Task TrackUpdate(ITelegramBotClient botClient, CancellationToken t
             ];
         }
 
-        #region Before Command Middleware
+        var middlewarePassed = await ExecuteBeforeMiddlewareAsync(commandContext);
+        if (!middlewarePassed)
+        {
+            return null;
+        }
 
+        #region Invoke Command
+
+        var controller = (BotCommandController)ActivatorUtilities.CreateInstance(provider, botCommandInfo.ControllerType);
+        controller.Context = commandContext;
+
+        logger.LogTrace("Invoking command: {Controller}/{Method}", botCommandInfo.ControllerType.Name, botCommandInfo.Method.Name);
+        var invokeResult = await MethodHelper.InvokeMethod(botCommandInfo.Method, paramList, controller);
+        logger.LogDebug("Successfully handled UpdateId: {UpdateId} for {UpdateType} ", botCommandInfo.Update!.Id, botCommandInfo.Update!.Type);
+
+        #endregion
+
+        await ExecuteAfterMiddlewareAsync(commandContext);
+        
+        return invokeResult;
+    }
+
+    private async Task<bool> ExecuteBeforeMiddlewareAsync(CommandContext commandContext)
+    {
         var beforeCommands = provider.GetServices<IBeforeCommand>()
             .Where(x => x.GetType().GetCustomAttribute<DisabledMiddlewareAttribute>() == null)
             .Where(x => botEngineConfig.DisabledMiddleware?.Contains(x.GetType().Name) == false)
             .ToList();
 
         var passedMiddlewareCount = 0;
 
+        logger.LogTrace("Found {Count} BeforeMiddlewares", beforeCommands.Count);
         foreach (var command in beforeCommands)
         {
             var middlewareName = command.GetType().Name;
@@ -167,27 +200,20 @@ await command.ExecuteAsync(commandContext, data =>
         {
             logger.LogDebug("Handler stops because middleware is not passed");
 
-            return null;
+            return false;
         }
 
-        #endregion
-
-        #region Invoke Command
-
-        var controller = (BotCommandController)ActivatorUtilities.CreateInstance(provider, botCommandInfo.ControllerType);
-        controller.Context = commandContext;
-
-        var invokeResult = await MethodHelper.InvokeMethod(botCommandInfo.Method, paramList, controller);
-        logger.LogDebug("Successfully handled UpdateId: {UpdateId} for {UpdateType} ", botCommandInfo.Update!.Id, botCommandInfo.Update!.Type);
-
-        #endregion
-
-        #region After Command Middleware
+        logger.LogTrace("All BeforeMiddlewares passed");
+        return true;
+    }
 
+    private async Task ExecuteAfterMiddlewareAsync(CommandContext commandContext)
+    {
         var afterCommands = provider.GetServices<IAfterCommand>()
             .Where(x => x.GetType().GetCustomAttribute<DisabledMiddlewareAttribute>() == null)
             .ToList();
 
+        logger.LogTrace("Found {Count} AfterMiddlewares", afterCommands.Count);
         foreach (var command in afterCommands)
         {
             var middlewareName = command.GetType().Name;
@@ -196,14 +222,10 @@ await command.ExecuteAsync(commandContext, data =>
             await command.ExecuteAsync(commandContext);
             logger.LogDebug("AfterMiddleware - Complete: {Middleware}", middlewareName);
         }
-
-        #endregion
-
-        return invokeResult;
     }
 
     #endregion
-
+    
     #region Command
 
     private BotCommandInfo? GetMethod(Update update)

ZiziBot.TelegramBot.Framework/Models/Configs/BotEngineConfig.cs

@@ -4,7 +4,7 @@ namespace ZiziBot.TelegramBot.Framework.Models.Configs;
 
 public class BotEngineConfig
 {
-    public const string CONFIG_PATH = "BotEngine";
+    public const string ConfigPath = "BotEngine";
 
     public string? WebhookUrl { get; set; }
     public BotEngineMode EngineMode { get; set; }

ZiziBot.TelegramBot.Framework/Models/Configs/BotTokenConfig.cs

@@ -2,7 +2,7 @@
 
 public class BotTokenConfig
 {
-    public const string CONFIG_PATH = "BotEngine:Bot";
+    public const string ConfigPath = "BotEngine:Bot";
 
     public required string Name { get; set; }
     public required string Token { get; set; }

ZiziBot.TelegramBot.Sample/Program.cs

@@ -4,7 +4,7 @@
 var builder = WebApplication.CreateBuilder(args);
 
 builder.Services.AddSerilog(x => x
-    .MinimumLevel.Debug()
+    .MinimumLevel.Verbose()
     .WriteTo.Console());
 
 builder.Services.AddZiziBotTelegramBot();