diff --git a/JSMR.Application/Scanning/ScanVoiceWorksHandler.cs b/JSMR.Application/Scanning/ScanVoiceWorksHandler.cs index e29d860..c83ea41 100644 --- a/JSMR.Application/Scanning/ScanVoiceWorksHandler.cs +++ b/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 logger, IVoiceWorkScannerRepository scannerRepository, IVoiceWorkUpdaterRepository updaterRepository, ISpamCircleCache spamCircleCache, @@ -13,43 +16,148 @@ public sealed class ScanVoiceWorksHandler( { public async Task 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 { + ["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; + } } } \ No newline at end of file diff --git a/JSMR.Worker/JSMR.Worker.csproj b/JSMR.Worker/JSMR.Worker.csproj index c767f1f..1cff84c 100644 --- a/JSMR.Worker/JSMR.Worker.csproj +++ b/JSMR.Worker/JSMR.Worker.csproj @@ -31,6 +31,8 @@ + + diff --git a/JSMR.Worker/Program.cs b/JSMR.Worker/Program.cs index ea28355..731803d 100644 --- a/JSMR.Worker/Program.cs +++ b/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()