jsmr/JSMR.Application/Scanning/ScanVoiceWorksHandler.cs

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,
    IVoiceWorkIngestBuilder ingestBuilder,
    IVoiceWorkSearchUpdater searchUpdater)
{
    public async Task<ScanVoiceWorksResponse> HandleAsync(ScanVoiceWorksRequest request, CancellationToken cancellationToken)
    {
        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: upsertResults,
                EndOfResults: false
            );
        }
        catch (Exception ex)
        {
            stopwatch.Stop();

            logger.LogError(
                ex,
                "Scan handler failed during phase {Phase} for page {PageNumber} after {ElapsedMs} ms",
                currentPhase,
                request.PageNumber,
                stopwatch.ElapsedMilliseconds);

            throw;
        }
    }
}