feat(backend): improve logging for gateway and analysis services

ScriptBeeWebApp/src/Analysis/Adapters/Analysis.Web/BackgroundServices/RunScriptBackgroundService.cs

@@ -6,15 +6,52 @@ namespace ScriptBee.Analysis.Web.BackgroundServices;
 
 public class RunScriptBackgroundService(
     Channel<RunScriptRequest> runScriptChannel,
-    IRunScriptService runScriptService
+    IRunScriptService runScriptService,
+    ILogger<RunScriptBackgroundService> logger
 ) : BackgroundService
 {
     protected override async Task ExecuteAsync(CancellationToken stoppingToken)
     {
+        logger.LogInformation("Run Script Background Service is starting");
+
         while (await runScriptChannel.Reader.WaitToReadAsync(stoppingToken))
         {
-            var request = await runScriptChannel.Reader.ReadAsync(stoppingToken);
-            await runScriptService.RunAsync(request, stoppingToken);
+            RunScriptRequest? request = null;
+            try
+            {
+                request = await runScriptChannel.Reader.ReadAsync(stoppingToken);
+
+                logger.LogInformation(
+                    "Executing script {ScriptPath} for analysis {AnalysisId} on project {ProjectId}",
+                    request.Script.File.Path,
+                    request.AnalysisInfo.Id,
+                    request.Script.ProjectId
+                );
+
+                await runScriptService.RunAsync(request, stoppingToken);
+
+                logger.LogInformation(
+                    "Script {ScriptPath} completed for analysis {AnalysisId}",
+                    request.Script.File.Path,
+                    request.AnalysisInfo.Id
+                );
+            }
+            catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested)
+            {
+                logger.LogInformation("Run Script Background Service is stopping");
+                break;
+            }
+            catch (Exception e)
+            {
+                logger.LogError(
+                    e,
+                    "Unhandled error while executing script {ScriptPath} for analysis {AnalysisId}",
+                    request?.Script.File.Path,
+                    request?.AnalysisInfo.Id
+                );
+            }
         }
+
+        logger.LogInformation("Run Script Background Service has stopped");
     }
 }

ScriptBeeWebApp/src/Analysis/Adapters/Analysis.Web/Program.cs

@@ -7,6 +7,7 @@
 using ScriptBee.Common.Web.EndpointDefinition;
 using ScriptBee.Common.Web.Extensions;
 using Serilog;
+using Serilog.Events;
 
 var builder = WebApplication.CreateBuilder(args);
 
@@ -66,7 +67,23 @@
 
 app.MapHealthChecksEndpoint();
 
-app.UseSerilogRequestLogging();
+app.UseSerilogRequestLogging(options =>
+{
+    options.GetLevel = (ctx, _, ex) =>
+        ex is not null ? LogEventLevel.Error
+        : ctx.Request.Path.StartsWithSegments("/health") ? LogEventLevel.Debug
+        : LogEventLevel.Information;
+
+    options.EnrichDiagnosticContext = (diagnosticContext, httpContext) =>
+    {
+        diagnosticContext.Set("RequestHost", httpContext.Request.Host.Value);
+        diagnosticContext.Set("RequestScheme", httpContext.Request.Scheme);
+        if (httpContext.Request.Headers.TryGetValue("X-Client-Id", out var clientId))
+        {
+            diagnosticContext.Set("ClientId", clientId.ToString());
+        }
+    };
+});
 
 app.UseExceptionEndpoint();
 

ScriptBeeWebApp/src/Analysis/Application/Service.Analysis/InstallPluginService.cs

@@ -1,3 +1,4 @@
+using Microsoft.Extensions.Logging;
 using OneOf;
 using OneOf.Types;
 using ScriptBee.Domain.Model.Plugins;
@@ -13,13 +14,20 @@ public class InstallPluginService(
     IProjectManager projectManager,
     IPluginReader pluginReader,
     IPluginLoader pluginLoader,
-    IPluginPathProvider pluginPathProvider
+    IPluginPathProvider pluginPathProvider,
+    ILogger<InstallPluginService> logger
 ) : IInstallPluginUseCase
 {
     public OneOf<Success, InvalidPluginError, PluginInstallationError> InstallPlugin(
         PluginId pluginId
     )
     {
+        logger.LogInformation(
+            "Installing plugin {PluginName} {PluginVersion} on analysis instance",
+            pluginId.Name,
+            pluginId.Version
+        );
+
         try
         {
             var projectId = ProjectId.FromValue(projectManager.GetProject().Id);
@@ -30,14 +38,32 @@ PluginId pluginId
 
             if (plugin is null)
             {
+                logger.LogWarning(
+                    "Plugin {PluginName} {PluginVersion} not found in project or global plugin paths",
+                    pluginId.Name,
+                    pluginId.Version
+                );
                 return new InvalidPluginError(pluginId);
             }
 
             pluginLoader.Load(plugin);
+
+            logger.LogInformation(
+                "Plugin {PluginName} {PluginVersion} installed on analysis instance",
+                pluginId.Name,
+                pluginId.Version
+            );
+
             return new Success();
         }
-        catch
+        catch (Exception e)
         {
+            logger.LogError(
+                e,
+                "Failed to install plugin {PluginName} {PluginVersion} on analysis instance",
+                pluginId.Name,
+                pluginId.Version
+            );
             return new PluginInstallationError(pluginId);
         }
     }

ScriptBeeWebApp/src/Analysis/Application/Service.Analysis/LoadModelFilesService.cs

@@ -1,5 +1,6 @@
 using DxWorks.ScriptBee.Plugin.Api;
 using DxWorks.ScriptBee.Plugin.Api.Model;
+using Microsoft.Extensions.Logging;
 using ScriptBee.Artifacts;
 using ScriptBee.Domain.Model.File;
 using ScriptBee.Plugins.Loader;
@@ -9,7 +10,8 @@ namespace ScriptBee.Service.Analysis;
 public class LoadModelFilesService(
     IProjectManager projectManager,
     IPluginRepository pluginRepository,
-    IFileModelService fileModelService
+    IFileModelService fileModelService,
+    ILogger<LoadModelFilesService> logger
 ) : ILoadModelFilesService
 {
     public async Task LoadModelFiles(
@@ -25,9 +27,14 @@ public async Task LoadModelFiles(
 
             if (modelLoader is null)
             {
+                logger.LogWarning(
+                    "No model loader plugin found for loader '{LoaderId}' — files will be skipped",
+                    loader
+                );
                 continue;
             }
 
+            logger.LogDebug("Loading model files with loader '{LoaderId}'", loader);
             await LoadModelFiles(fileIds, modelLoader, loader, loadModels, cancellationToken);
         }
     }
@@ -53,6 +60,12 @@ CancellationToken cancellationToken
             cancellationToken: cancellationToken
         );
 
+        logger.LogDebug(
+            "Loader '{LoaderId}' produced {TypeCount} model type(s)",
+            loader,
+            dictionary.Count
+        );
+
         projectManager.AddToGivenProject(dictionary, modelLoader.GetName());
 
         AddToLoadedModels(dictionary, loader, loadModels);

ScriptBeeWebApp/src/Analysis/Application/Service.Analysis/RunAnalysisService.cs

@@ -1,5 +1,6 @@
 using System.Threading.Channels;
 using DxWorks.ScriptBee.Plugin.Api;
+using Microsoft.Extensions.Logging;
 using OneOf;
 using ScriptBee.Analysis;
 using ScriptBee.Artifacts;
@@ -19,20 +20,32 @@ public class RunAnalysisService(
     IGetScripts getScripts,
     IPluginRepository pluginRepository,
     Channel<RunScriptRequest> runScriptChannel,
-    InstanceInformation instanceInformation
+    InstanceInformation instanceInformation,
+    ILogger<RunAnalysisService> logger
 ) : IRunAnalysisUseCase
 {
     public async Task<AnalysisInfo> Run(
         RunAnalysisCommand command,
         CancellationToken cancellationToken = default
     )
     {
+        logger.LogInformation(
+            "Starting analysis for script {ScriptId} on project {ProjectId}",
+            command.ScriptId,
+            command.ProjectId
+        );
+
         var scriptResult = await getScripts.Get(command.ScriptId, cancellationToken);
 
         return await scriptResult.Match(
             async script => await Run(script, cancellationToken),
             async error =>
-                await createAnalysis.Create(
+            {
+                logger.LogWarning(
+                    "Script {ScriptId} not found — analysis will be recorded as failed to start",
+                    command.ScriptId
+                );
+                return await createAnalysis.Create(
                     AnalysisInfo.FailedToStart(
                         new AnalysisId(guidProvider.NewGuid()),
                         command.ProjectId,
@@ -42,7 +55,8 @@ await createAnalysis.Create(
                         error.ToString()
                     ),
                     cancellationToken
-                )
+                );
+            }
         );
     }
 
@@ -56,7 +70,12 @@ private async Task<AnalysisInfo> Run(
         return await scriptRunnerResult.Match(
             async runner => await Run(runner, script, cancellationToken),
             async error =>
-                await createAnalysis.Create(
+            {
+                logger.LogWarning(
+                    "No script runner found for language {Language} — analysis will be recorded as failed to start",
+                    script.ScriptLanguage.Name
+                );
+                return await createAnalysis.Create(
                     AnalysisInfo.FailedToStart(
                         new AnalysisId(guidProvider.NewGuid()),
                         script.ProjectId,
@@ -66,7 +85,8 @@ await createAnalysis.Create(
                         error.ToString()
                     ),
                     cancellationToken
-                )
+                );
+            }
         );
     }
 
@@ -87,6 +107,12 @@ private async Task<AnalysisInfo> Run(
             cancellationToken
         );
 
+        logger.LogInformation(
+            "Analysis {AnalysisId} created — queuing script {ScriptPath} for execution",
+            analysisInfo.Id,
+            script.File.Path
+        );
+
         await runScriptChannel.Writer.WriteAsync(
             new RunScriptRequest(scriptRunner, script, analysisInfo),
             cancellationToken

ScriptBeeWebApp/src/Analysis/Application/Service.Analysis/RunScriptService.cs

@@ -1,6 +1,7 @@
 using System.Text;
 using DxWorks.ScriptBee.Plugin.Api;
 using DxWorks.ScriptBee.Plugin.Api.Services;
+using Microsoft.Extensions.Logging;
 using ScriptBee.Analysis;
 using ScriptBee.Artifacts;
 using ScriptBee.Common;
@@ -18,7 +19,8 @@ public sealed class RunScriptService(
     IDateTimeProvider dateTimeProvider,
     IGuidProvider guidProvider,
     IPluginRepository pluginRepository,
-    IProjectManager projectManager
+    IProjectManager projectManager,
+    ILogger<RunScriptService> logger
 ) : IRunScriptService
 {
     public async Task RunAsync(
@@ -38,7 +40,14 @@ await scriptContent.Match(
                 await RunScript(request, content, cancellationToken);
             },
             async error =>
-                await UpdateAnalysisFileNotFound(request.AnalysisInfo, error, cancellationToken)
+            {
+                logger.LogWarning(
+                    "Script file not found for analysis {AnalysisId}: {Error}",
+                    request.AnalysisInfo.Id,
+                    error
+                );
+                await UpdateAnalysisFileNotFound(request.AnalysisInfo, error, cancellationToken);
+            }
         );
     }
 
@@ -48,6 +57,12 @@ private async Task RunScript(
         CancellationToken cancellationToken
     )
     {
+        logger.LogDebug(
+            "Saving script file snapshot for analysis {AnalysisId} (language: {Language})",
+            request.AnalysisInfo.Id,
+            request.Script.ScriptLanguage.Name
+        );
+
         var metadata = new HistoricalScriptMetadata(
             request.Script.File.Path,
             request.Script.ScriptLanguage.Name,
@@ -59,13 +74,25 @@ CancellationToken cancellationToken
         var analysisInfo = request.AnalysisInfo with { ScriptFileId = scriptFileId };
         await updateAnalysis.Update(analysisInfo, cancellationToken);
 
+        logger.LogDebug(
+            "Running script for analysis {AnalysisId} with runner {Runner}",
+            request.AnalysisInfo.Id,
+            request.ScriptRunner.GetType().Name
+        );
+
         var results = await RunScriptAsync(
             request.ScriptRunner,
             request.Script,
             content,
             cancellationToken
         );
 
+        logger.LogDebug(
+            "Script execution finished for analysis {AnalysisId} — {ResultCount} result(s) produced",
+            request.AnalysisInfo.Id,
+            results.Count
+        );
+
         await updateAnalysis.Update(
             analysisInfo.Success(dateTimeProvider.UtcNow(), results),
             cancellationToken
@@ -128,6 +155,13 @@ await scriptRunner.RunAsync(
         }
         catch (Exception e)
         {
+            logger.LogError(
+                e,
+                "Script runner threw an exception for script {ScriptPath} (language: {Language})",
+                script.File.Path,
+                script.ScriptLanguage.Name
+            );
+
             var runErrorId = await SaveStringContentToFile<object>(
                 e.Message,
                 null,