Added logging to scanner.

JSMR.Application/Scanning/ScanVoiceWorksHandler.cs

@@ -1,10 +1,13 @@
 using JSMR.Application.Common.Caching;
 using JSMR.Application.Scanning.Contracts;
 using JSMR.Application.Scanning.Ports;
+using Microsoft.Extensions.Logging;
+using System.Diagnostics;
 
 namespace JSMR.Application.Scanning;
 
 public sealed class ScanVoiceWorksHandler(
+    ILogger<ScanVoiceWorksHandler> logger,
     IVoiceWorkScannerRepository scannerRepository,
     IVoiceWorkUpdaterRepository updaterRepository,
     ISpamCircleCache spamCircleCache,
@@ -13,43 +16,148 @@ public sealed class ScanVoiceWorksHandler(
 {
     public async Task<ScanVoiceWorksResponse> HandleAsync(ScanVoiceWorksRequest request, CancellationToken cancellationToken)
     {
-        IVoiceWorksScanner? scanner = scannerRepository.GetScanner(request.Locale);
-        IVoiceWorkUpdater? updater = updaterRepository.GetUpdater(request.Locale);
-
-        if (scanner is null)
-            throw new InvalidOperationException($"No scanner registered for locale {request.Locale}.");
-
-        if (updater is null)
-            throw new InvalidOperationException($"No updater registered for locale {request.Locale}.");
-
-        VoiceWorkScanOptions options = new(
-            PageNumber: request.PageNumber,
-            PageSize: request.PageSize,
-            ExcludedMakerIds: await spamCircleCache.GetAsync(cancellationToken),
-            ExcludePartiallyAIGeneratedWorks: true,
-            ExcludeAIGeneratedWorks: true
-        );
-
-        VoiceWorkScanResult scanResult = await scanner.ScanPageAsync(options, cancellationToken);
-
-        if (scanResult.EndOfResults)
+        using IDisposable? scope = logger.BeginScope(new Dictionary<string, object>
         {
+            ["Locale"] = request.Locale,
+            ["PageNumber"] = request.PageNumber,
+            ["PageSize"] = request.PageSize
+        });
+
+        Stopwatch stopwatch = Stopwatch.StartNew();
+        string currentPhase = "initialization";
+
+        try
+        {
+            logger.LogInformation(
+                "Starting scan handler for page {PageNumber}, page size {PageSize}, locale {Locale}",
+                request.PageNumber,
+                request.PageSize,
+                request.Locale);
+
+            currentPhase = "resolve_scanner";
+            IVoiceWorksScanner? scanner = scannerRepository.GetScanner(request.Locale);
+
+            currentPhase = "resolve_updater";
+            IVoiceWorkUpdater? updater = updaterRepository.GetUpdater(request.Locale);
+
+            if (scanner is null)
+                throw new InvalidOperationException($"No scanner registered for locale {request.Locale}.");
+
+            if (updater is null)
+                throw new InvalidOperationException($"No updater registered for locale {request.Locale}.");
+
+            currentPhase = "load_spam_circle_cache";
+            var spamStopwatch = Stopwatch.StartNew();
+
+            string[] excludedMakerIds = await spamCircleCache.GetAsync(cancellationToken);
+
+            spamStopwatch.Stop();
+            logger.LogInformation(
+                "Loaded spam circle cache in {ElapsedMs} ms. ExcludedMakerCount={ExcludedMakerCount}",
+                spamStopwatch.ElapsedMilliseconds,
+                excludedMakerIds.Length);
+
+            VoiceWorkScanOptions options = new(
+                PageNumber: request.PageNumber,
+                PageSize: request.PageSize,
+                ExcludedMakerIds: excludedMakerIds,
+                ExcludePartiallyAIGeneratedWorks: true,
+                ExcludeAIGeneratedWorks: true
+            );
+
+            currentPhase = "scan_page";
+            var scanStopwatch = Stopwatch.StartNew();
+
+            VoiceWorkScanResult scanResult = await scanner.ScanPageAsync(options, cancellationToken);
+
+            scanStopwatch.Stop();
+
+            logger.LogInformation(
+                "Scanned source page in {ElapsedMs} ms. EndOfResults={EndOfResults}, ResultCount={ResultCount}",
+                scanStopwatch.ElapsedMilliseconds,
+                scanResult.EndOfResults,
+                scanResult.Works.Length);
+
+
+            if (scanResult.EndOfResults)
+            {
+                stopwatch.Stop();
+
+                logger.LogInformation(
+                    "End of results reached for page {PageNumber}. TotalElapsedMs={ElapsedMs}",
+                    request.PageNumber,
+                    stopwatch.ElapsedMilliseconds);
+
+                return new ScanVoiceWorksResponse(
+                    Results: [],
+                    EndOfResults: true
+                );
+            }
+
+            currentPhase = "build_ingests";
+            var ingestSw = Stopwatch.StartNew();
+
+            VoiceWorkIngest[] ingests = await ingestBuilder.BuildAsync(scanResult, cancellationToken);
+
+            ingestSw.Stop();
+            logger.LogInformation(
+                "Built ingests in {ElapsedMs} ms. IngestCount={IngestCount}",
+                ingestSw.ElapsedMilliseconds,
+                ingests.Length);
+
+            currentPhase = "upsert_voiceworks";
+            var upsertSw = Stopwatch.StartNew();
+
+            VoiceWorkUpsertResult[] upsertResults = await updater.UpsertAsync(ingests, cancellationToken);
+
+            upsertSw.Stop();
+
+            int[] voiceWorkIds = [.. upsertResults.Where(x => x.VoiceWorkId.HasValue).Select(x => x.VoiceWorkId!.Value)];
+
+            int issueCount = upsertResults.Sum(x => x.Issues.Count);
+
+            logger.LogInformation(
+                "Upserted voice works in {ElapsedMs} ms. UpsertResultCount={UpsertResultCount}, VoiceWorkIdCount={VoiceWorkIdCount}, IssueCount={IssueCount}",
+                upsertSw.ElapsedMilliseconds,
+                upsertResults.Length,
+                voiceWorkIds.Length,
+                issueCount);
+
+            currentPhase = "update_search";
+            var searchSw = Stopwatch.StartNew();
+
+            await searchUpdater.UpdateAsync(voiceWorkIds, cancellationToken);
+
+            searchSw.Stop();
+            logger.LogInformation(
+                "Updated search index in {ElapsedMs} ms. VoiceWorkIdCount={VoiceWorkIdCount}",
+                searchSw.ElapsedMilliseconds,
+                voiceWorkIds.Length);
+
+            stopwatch.Stop();
+
+            logger.LogInformation(
+                "Completed scan handler for page {PageNumber} in {ElapsedMs} ms",
+                request.PageNumber,
+                stopwatch.ElapsedMilliseconds);
+
             return new ScanVoiceWorksResponse(
-                Results: [],
-                EndOfResults: true
+                Results: upsertResults,
+                EndOfResults: false
             );
         }
+        catch (Exception ex)
+        {
+            stopwatch.Stop();
 
-        VoiceWorkIngest[] ingests = await ingestBuilder.BuildAsync(scanResult, cancellationToken);
+            logger.LogError(
+                ex,
+                "Scan handler failed during phase {Phase} for page {PageNumber} after {ElapsedMs} ms",
+                currentPhase,
+                request.PageNumber,
+                stopwatch.ElapsedMilliseconds);
 
-        VoiceWorkUpsertResult[] upsertResults = await updater.UpsertAsync(ingests, cancellationToken);
-        int[] voiceWorkIds = [.. upsertResults.Where(x => x.VoiceWorkId.HasValue).Select(x => x.VoiceWorkId!.Value)];
-
-        await searchUpdater.UpdateAsync(voiceWorkIds, cancellationToken);
-
-        return new ScanVoiceWorksResponse(
-            Results: upsertResults,
-            EndOfResults: false
-        );
+            throw;
+        }
     }
 }

JSMR.Worker/JSMR.Worker.csproj

@@ -31,6 +31,8 @@
     <PackageReference Include="Serilog.Extensions.Hosting" Version="10.0.0" />
     <PackageReference Include="Serilog.Settings.Configuration" Version="10.0.0" />
     <PackageReference Include="Serilog.Sinks.Console" Version="6.1.1" />
+    <PackageReference Include="Serilog.Sinks.File" Version="7.0.0" />
+    <PackageReference Include="Serilog.Sinks.Seq" Version="9.0.0" />
     <PackageReference Include="Spectre.Console" Version="0.55.2" />
     <PackageReference Include="System.CommandLine" Version="2.0.7" />
   </ItemGroup>

JSMR.Worker/Program.cs

@@ -7,7 +7,9 @@ using Microsoft.EntityFrameworkCore;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
 using Serilog;
+using Serilog.Events;
 using System.CommandLine;
 using System.Text;
 
@@ -29,9 +31,23 @@ if (builder.Environment.IsDevelopment())
 string connectionString = builder.Configuration.GetConnectionString("AppDb")
     ?? throw new InvalidOperationException("Missing ConnectionStrings:AppDb");
 
-//builder.Services.AddSerilog(o => o
-//    .WriteTo.Console()
-//    .MinimumLevel.Warning());
+string? seqUrl = builder.Configuration["Seq:ServerUrl"];
+
+Log.Logger = new LoggerConfiguration()
+    .MinimumLevel.Information()
+    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
+    .MinimumLevel.Override("System", LogEventLevel.Warning)
+    .MinimumLevel.Override("Polly", LogEventLevel.Warning)
+    .WriteTo.Logger(lc => lc
+        .MinimumLevel.Warning()
+        .WriteTo.Console())
+    .WriteTo.File(
+        path: "logs/jsmr-worker-.log",
+        rollingInterval: RollingInterval.Day)
+    .CreateLogger();
+
+builder.Logging.ClearProviders();
+builder.Services.AddSerilog();
 
 builder.Services
     .AddApplication()