Add inactivity safeguard and speaker diagnostics

MeetingAssistant/Speakers/SpeakerIdentityService.cs

@@ -67,18 +67,32 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
 
         var sourceLabel = sourceSpeaker.Trim();
         var targetName = targetSpeaker.Trim();
+        logger.LogInformation(
+            "Applying speaker override from {SourceSpeaker} to {TargetSpeaker} for meeting {MeetingNotePath}",
+            sourceLabel,
+            targetName,
+            request.MeetingNote.Path);
         await using var context = await dbContextFactory.CreateDbContextAsync(cancellationToken);
         await SpeakerIdentitySchema.EnsureCreatedOrUpdatedAsync(context, cancellationToken);
 
         var now = DateTimeOffset.UtcNow;
         var meetingReference = CreateReference(request.MeetingNote, now);
-        var snippet = await ResolveOverrideSnippetAsync(request, sourceLabel, cancellationToken);
+        var snippetResolution = await ResolveOverrideSnippetAsync(request, sourceLabel, cancellationToken);
+        var snippet = snippetResolution.WavBytes;
         var target = await FindIdentityByAcceptedNameAsync(context, targetName, cancellationToken);
         var sourceCandidate = await FindCurrentRunCandidateAsync(
             context,
             meetingReference,
             targetName,
             cancellationToken);
+        logger.LogInformation(
+            "Speaker override from {SourceSpeaker} to {TargetSpeaker} resolved sample source {SampleSource}, sample bytes {SampleBytes}, target identity {TargetIdentityId}, source candidate identity {SourceCandidateIdentityId}",
+            sourceLabel,
+            targetName,
+            snippetResolution.Source,
+            snippet.Length,
+            target?.Id,
+            sourceCandidate?.Id);
 
         if (target is null)
         {
@@ -99,10 +113,19 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             if (target.Id == 0)
             {
                 context.SpeakerIdentities.Add(target);
+                logger.LogInformation(
+                    "Creating speaker identity from override for {TargetSpeaker} using source {SourceSpeaker}",
+                    targetName,
+                    sourceLabel);
             }
         }
         else if (sourceCandidate is not null && sourceCandidate.Id != target.Id)
         {
+            logger.LogInformation(
+                "Merging override source candidate identity {SourceCandidateIdentityId} into target identity {TargetIdentityId} for {TargetSpeaker}",
+                sourceCandidate.Id,
+                target.Id,
+                targetName);
             MergeOverrideCandidate(target, sourceCandidate);
             context.SpeakerIdentities.Remove(sourceCandidate);
         }
@@ -111,8 +134,16 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
         target.UpdatedAt = now;
         ResetCandidates(target, [targetName]);
         AddMeetingReference(target, meetingReference);
-        AddSnippetIfNeeded(target, snippet);
+        var snippetAdded = AddSnippetIfNeeded(target, snippet);
         await context.SaveChangesAsync(cancellationToken);
+        logger.LogInformation(
+            "Applied speaker override from {SourceSpeaker} to {TargetSpeaker}: identity {IdentityId}, snippet added {SnippetAdded}, snippet count {SnippetCount}, reference count {ReferenceCount}",
+            sourceLabel,
+            targetName,
+            target.Id,
+            snippetAdded,
+            target.Snippets.Count,
+            target.References.Count);
         await SpeakerIdentityTranscriptAudit.AppendIdentifiedAsync(
             target.References,
             sourceLabel,
@@ -134,9 +165,20 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
         var target = await FindIdentityByAcceptedNameAsync(context, identity.Trim(), cancellationToken);
         if (target is null)
         {
+            logger.LogInformation(
+                "Speaker identity deletion skipped because {IdentityName} was not found",
+                identity.Trim());
             return;
         }
 
+        logger.LogInformation(
+            "Deleting speaker identity {IdentityId} ({IdentityName}) with {SnippetCount} snippet(s), {CandidateCount} candidate(s), {AliasCount} alias(es), {ReferenceCount} reference(s)",
+            target.Id,
+            target.GetDisplayName() ?? identity.Trim(),
+            target.Snippets.Count,
+            target.CandidateNames.Count,
+            target.Aliases.Count,
+            target.References.Count);
         context.SpeakerIdentities.Remove(target);
         await context.SaveChangesAsync(cancellationToken);
     }
@@ -180,6 +222,15 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             matchedAcceptedNames.Add(name);
         }
 
+        logger.LogInformation(
+            "Speaker identity processing started in {Mode} mode for meeting {MeetingNotePath}: {SegmentCount} segment(s), {SampleCount} supplied sample(s), {KnownMappingCount} known mapping(s), attendees {Attendees}",
+            mode,
+            request.MeetingNote.Path,
+            request.Segments.Count,
+            request.Samples?.Count ?? 0,
+            knownSpeakerMappings.Count,
+            FormatNames(attendees));
+
         var unmatchedSpeakers = new List<(string Speaker, byte[] Snippet)>();
         var samplesBySpeaker = request.Samples?
             .Where(sample => !string.IsNullOrWhiteSpace(sample.Speaker) && sample.WavBytes.Length > 0)
@@ -189,6 +240,12 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
                 group => group.OrderByDescending(sample => sample.Score).Select(sample => sample.WavBytes).First(),
                 StringComparer.OrdinalIgnoreCase)
             ?? new Dictionary<string, byte[]>(StringComparer.OrdinalIgnoreCase);
+        if (samplesBySpeaker.Count > 0)
+        {
+            logger.LogInformation(
+                "Speaker identity processing has supplied samples for {SampleSpeakers}",
+                string.Join(", ", samplesBySpeaker.Select(pair => $"{pair.Key}:{pair.Value.Length} bytes")));
+        }
 
         foreach (var group in request.Segments
             .Where(segment => !string.IsNullOrWhiteSpace(segment.Speaker))
@@ -198,26 +255,55 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             var speaker = group.Key;
             if (knownDiarizedSpeakers.Contains(speaker) || alreadyIdentifiedNames.Contains(speaker))
             {
+                logger.LogInformation(
+                    "Speaker identity processing skipped {Speaker} because it is already known or identified",
+                    speaker);
                 continue;
             }
 
             if (speakerMappings.ContainsKey(speaker))
             {
+                logger.LogInformation(
+                    "Speaker identity processing skipped {Speaker} because a mapping already exists to {MappedSpeaker}",
+                    speaker,
+                    speakerMappings[speaker]);
                 continue;
             }
 
+            var snippetSource = "supplied";
             var snippet = samplesBySpeaker.TryGetValue(speaker, out var suppliedSnippet)
                 ? suppliedSnippet
-                : await snippetExtractor.ExtractSnippetAsync(
-                    request.AudioPath,
-                    SpeakerSampleSpanSelector.SelectBestContinuousSpan(
-                        request.Segments,
-                        speaker,
-                        options.MaximumSampleSegmentGap,
-                        options.MinimumSampleSpeechDuration),
-                    cancellationToken);
+                : [];
             if (snippet.Length == 0)
             {
+                snippetSource = "extracted";
+                var span = SpeakerSampleSpanSelector.SelectBestContinuousSpan(
+                    request.Segments,
+                    speaker,
+                    options.MaximumSampleSegmentGap,
+                    options.MinimumSampleSpeechDuration);
+                logger.LogInformation(
+                    "Speaker identity processing extracting sample for {Speaker}: selected {SegmentCount} segment(s), span {SpanDuration}, minimum {MinimumDuration}",
+                    speaker,
+                    span.Count,
+                    SpeakerSampleSpanSelector.SpanDuration(span),
+                    options.MinimumSampleSpeechDuration);
+                snippet = await snippetExtractor.ExtractSnippetAsync(
+                    request.AudioPath,
+                    span,
+                    cancellationToken);
+            }
+
+            logger.LogInformation(
+                "Speaker identity processing resolved {SampleSource} sample for {Speaker}: {SampleBytes} byte(s)",
+                snippetSource,
+                speaker,
+                snippet.Length);
+            if (snippet.Length == 0)
+            {
+                logger.LogInformation(
+                    "Speaker identity processing cannot match or learn {Speaker} because no usable sample was available",
+                    speaker);
                 unmatchedSpeakers.Add((speaker, snippet));
                 continue;
             }
@@ -231,6 +317,9 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
                 cancellationToken);
             if (match is null)
             {
+                logger.LogInformation(
+                    "Speaker identity processing found no existing identity match for {Speaker}",
+                    speaker);
                 unmatchedSpeakers.Add((speaker, snippet));
                 continue;
             }
@@ -238,6 +327,10 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             var identity = await LoadIdentityAsync(context, match.IdentityId, cancellationToken);
             if (identity is null)
             {
+                logger.LogWarning(
+                    "Speaker identity processing matched {Speaker} to identity {IdentityId}, but the identity could not be loaded",
+                    speaker,
+                    match.IdentityId);
                 unmatchedSpeakers.Add((speaker, snippet));
                 continue;
             }
@@ -247,6 +340,15 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
                 var previousCanonicalName = identity.CanonicalName;
                 AddMeetingReference(identity, meetingReference);
                 UpdateMatchedIdentity(identity, attendees, snippet);
+                logger.LogInformation(
+                    "Speaker identity processing updated matched identity {IdentityId} for {Speaker}: previous canonical {PreviousCanonicalName}, canonical {CanonicalName}, candidates {CandidateNames}, snippets {SnippetCount}, references {ReferenceCount}",
+                    identity.Id,
+                    speaker,
+                    previousCanonicalName,
+                    identity.CanonicalName,
+                    FormatNames(identity.CandidateNames.Select(candidate => candidate.Name)),
+                    identity.Snippets.Count,
+                    identity.References.Count);
                 if (string.IsNullOrWhiteSpace(previousCanonicalName) &&
                     !string.IsNullOrWhiteSpace(identity.CanonicalName))
                 {
@@ -279,18 +381,34 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             }
         }
 
+        IReadOnlyList<SpeakerIdentity> learnedIdentities = [];
         if (mode == SpeakerIdentityProcessingMode.Final)
         {
-            await LearnUnmatchedSpeakersAsync(
+            learnedIdentities = await LearnUnmatchedSpeakersAsync(
                 context,
                 attendees,
                 matchedAcceptedNames,
                 unmatchedSpeakers,
                 meetingReference,
                 cancellationToken);
+            logger.LogInformation(
+                "Speaker identity processing queued {LearnedIdentityCount} new unmatched speaker identity candidate(s)",
+                learnedIdentities.Count);
         }
 
         await context.SaveChangesAsync(cancellationToken);
+        if (learnedIdentities.Count > 0)
+        {
+            logger.LogInformation(
+                "Speaker identity processing saved learned identity candidate ids {IdentityIds}",
+                FormatIds(learnedIdentities.Select(identity => identity.Id)));
+        }
+        logger.LogInformation(
+            "Speaker identity processing completed in {Mode} mode for meeting {MeetingNotePath}: {MappingCount} mapping(s), {AttendeeMatchCount} attendee match(es)",
+            mode,
+            request.MeetingNote.Path,
+            speakerMappings.Count,
+            attendeeMatches.Count);
 
         var relabeledSegments = request.Segments
             .Select(segment => speakerMappings.TryGetValue(segment.Speaker, out var speakerName)
@@ -333,8 +451,16 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             .Select(candidate => candidate.Identity)
             .ToList();
 
+        logger.LogInformation(
+            "Speaker identity match candidate selection for {Speaker}: {CandidateCount} candidate(s) after active/attendee/name filters, ids {IdentityIds}",
+            speaker,
+            identities.Count,
+            FormatIds(identities.Select(identity => identity.Id)));
+
+        var round = 0;
         foreach (var batch in identities.Chunk(Math.Max(1, options.MatchBatchSize)))
         {
+            round++;
             var request = new SpeakerIdentityMatchRequest(
                 speaker,
                 snippet,
@@ -344,17 +470,31 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
                         identity.ReferenceCount,
                         identity.Snippets.Select(storedSnippet => storedSnippet.WavBytes).ToList()))
                     .ToList());
+            logger.LogInformation(
+                "Speaker identity match round {Round} for {Speaker}: candidate identity ids {IdentityIds}",
+                round,
+                speaker,
+                FormatIds(request.Candidates.Select(candidate => candidate.IdentityId)));
             var match = await matcher.MatchAsync(request, cancellationToken);
             if (match is not null)
             {
+                logger.LogInformation(
+                    "Speaker identity match round {Round} for {Speaker} matched identity {IdentityId}",
+                    round,
+                    speaker,
+                    match.IdentityId);
                 return match;
             }
         }
 
+        logger.LogInformation(
+            "Speaker identity match candidate selection for {Speaker} completed with no match after {RoundCount} round(s)",
+            speaker,
+            round);
         return null;
     }
 
-    private async Task<byte[]> ResolveOverrideSnippetAsync(
+    private async Task<SpeakerSnippetResolution> ResolveOverrideSnippetAsync(
         SpeakerIdentificationRequest request,
         string sourceSpeaker,
         CancellationToken cancellationToken)
@@ -365,15 +505,29 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             .FirstOrDefault();
         if (sample is not null)
         {
-            return sample.WavBytes;
+            return new SpeakerSnippetResolution(
+                sample.WavBytes,
+                "supplied-sample",
+                SegmentCount: 1,
+                sample.Score,
+                sample.Segment.End - sample.Segment.Start);
         }
 
         var segments = request.Segments
             .Where(segment => string.Equals(segment.Speaker, sourceSpeaker, StringComparison.OrdinalIgnoreCase))
             .ToList();
-        return segments.Count == 0
-            ? []
-            : await snippetExtractor.ExtractSnippetAsync(request.AudioPath, segments, cancellationToken);
+        if (segments.Count == 0)
+        {
+            return new SpeakerSnippetResolution([], "missing-segments", SegmentCount: 0, Score: null, Duration: TimeSpan.Zero);
+        }
+
+        var snippet = await snippetExtractor.ExtractSnippetAsync(request.AudioPath, segments, cancellationToken);
+        return new SpeakerSnippetResolution(
+            snippet,
+            "extracted-from-recording",
+            segments.Count,
+            Score: null,
+            segments.Max(segment => segment.End) - segments.Min(segment => segment.Start));
     }
 
     private static async Task<SpeakerIdentity?> FindIdentityByAcceptedNameAsync(
@@ -421,6 +575,10 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
         SpeakerIdentity target,
         SpeakerIdentity source)
     {
+        logger.LogInformation(
+            "Speaker override candidate merge started: source identity {SourceIdentityId} into target identity {TargetIdentityId}",
+            source.Id,
+            target.Id);
         AddAlias(target, source.CanonicalName);
         foreach (var alias in source.Aliases)
         {
@@ -441,6 +599,12 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
         {
             AddSnippetIfNeeded(target, snippet.WavBytes);
         }
+        logger.LogInformation(
+            "Speaker override candidate merge completed: target identity {TargetIdentityId} now has {AliasCount} alias(es), {SnippetCount} snippet(s), {ReferenceCount} reference(s)",
+            target.Id,
+            target.Aliases.Count,
+            target.Snippets.Count,
+            target.References.Count);
     }
 
     private static void AddAlias(SpeakerIdentity identity, string? alias)
@@ -526,22 +690,36 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
 
             if (intersection.Count == 0)
             {
+                logger.LogInformation(
+                    "Speaker identity candidate elimination for identity {IdentityId} had empty intersection; resetting candidates to attendees {Attendees} and replacing oldest snippet",
+                    identity.Id,
+                    FormatNames(attendees));
                 ResetCandidates(identity, attendees);
                 ReplaceOldestSnippet(identity, snippet);
                 return;
             }
 
+            logger.LogInformation(
+                "Speaker identity candidate elimination for identity {IdentityId}: candidates {CurrentCandidates}, attendees {Attendees}, intersection {Intersection}",
+                identity.Id,
+                FormatNames(currentCandidates),
+                FormatNames(attendees),
+                FormatNames(intersection));
             ResetCandidates(identity, intersection);
             if (intersection.Count == 1)
             {
                 identity.CanonicalName = intersection[0];
+                logger.LogInformation(
+                    "Speaker identity candidate elimination promoted identity {IdentityId} to canonical name {CanonicalName}",
+                    identity.Id,
+                    identity.CanonicalName);
             }
         }
 
         AddSnippetIfNeeded(identity, snippet);
     }
 
-    private async Task LearnUnmatchedSpeakersAsync(
+    private async Task<IReadOnlyList<SpeakerIdentity>> LearnUnmatchedSpeakersAsync(
         SpeakerIdentityDbContext context,
         IReadOnlyList<string> attendees,
         IEnumerable<string> matchedCanonicalNames,
@@ -555,16 +733,26 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             .ToList();
         if (remainingCandidates.Count == 0)
         {
-            return;
+            logger.LogInformation(
+                "Speaker identity candidate learning skipped because no attendee candidates remain. Matched names {MatchedNames}",
+                FormatNames(matchedCanonicalNames));
+            return [];
         }
 
+        logger.LogInformation(
+            "Speaker identity candidate learning started for {UnmatchedSpeakerCount} unmatched speaker(s) with remaining candidate names {CandidateNames}",
+            unmatchedSpeakers.Count,
+            FormatNames(remainingCandidates));
+        var learned = new List<SpeakerIdentity>();
         foreach (var (speaker, snippet) in unmatchedSpeakers.Where(speaker => speaker.Snippet.Length > 0))
         {
             if (!await matchValidator.ValidateSampleAsync(snippet, cancellationToken))
             {
                 logger.LogInformation(
-                    "Skipping speaker identity candidate for {Speaker} because secondary validation rejected the sample",
-                    speaker);
+                    "Skipping speaker identity candidate for {Speaker} because secondary validation rejected the sample: candidate names {CandidateNames}, sample bytes {SampleBytes}",
+                    speaker,
+                    FormatNames(remainingCandidates),
+                    snippet.Length);
                 continue;
             }
 
@@ -595,6 +783,14 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
                 ]
             };
             context.SpeakerIdentities.Add(identity);
+            learned.Add(identity);
+            logger.LogInformation(
+                "Created speaker identity candidate for {Speaker}: canonical {CanonicalName}, candidate names {CandidateNames}, sample bytes {SampleBytes}, meeting reference {MeetingNotePath}",
+                speaker,
+                canonicalName,
+                FormatNames(remainingCandidates),
+                snippet.Length,
+                meetingReference.MeetingNotePath);
             if (!string.IsNullOrWhiteSpace(canonicalName))
             {
                 await SpeakerIdentityTranscriptAudit.AppendIdentifiedAsync(
@@ -605,14 +801,22 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             }
         }
 
-        await Task.CompletedTask;
+        foreach (var (speaker, _) in unmatchedSpeakers.Where(speaker => speaker.Snippet.Length == 0))
+        {
+            logger.LogInformation(
+                "Skipping speaker identity candidate for {Speaker} because no sample was available: candidate names {CandidateNames}",
+                speaker,
+                FormatNames(remainingCandidates));
+        }
+
+        return learned;
     }
 
-    private void AddSnippetIfNeeded(SpeakerIdentity identity, byte[] snippet)
+    private bool AddSnippetIfNeeded(SpeakerIdentity identity, byte[] snippet)
     {
         if (snippet.Length == 0 || identity.Snippets.Count >= options.MaxSnippetsPerSpeaker)
         {
-            return;
+            return false;
         }
 
         identity.Snippets.Add(new SpeakerSnippet
@@ -620,6 +824,7 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
             WavBytes = snippet,
             CreatedAt = DateTimeOffset.UtcNow
         });
+        return true;
     }
 
     private static void ReplaceOldestSnippet(SpeakerIdentity identity, byte[] snippet)
@@ -700,6 +905,34 @@ public sealed class SpeakerIdentityService : ISpeakerIdentificationService
         SpeakerIdentityReferences.AddIfMissing(identity, reference, DateTimeOffset.UtcNow);
     }
 
+    private static string FormatNames(IEnumerable<string?> names)
+    {
+        var formatted = names
+            .Where(name => !string.IsNullOrWhiteSpace(name))
+            .Select(name => name!.Trim())
+            .Distinct(StringComparer.OrdinalIgnoreCase)
+            .Order(StringComparer.OrdinalIgnoreCase)
+            .ToList();
+        return formatted.Count == 0 ? "<none>" : string.Join(", ", formatted);
+    }
+
+    private static string FormatIds(IEnumerable<int> ids)
+    {
+        var formatted = ids
+            .Distinct()
+            .Order()
+            .Select(id => id.ToString(System.Globalization.CultureInfo.InvariantCulture))
+            .ToList();
+        return formatted.Count == 0 ? "<none>" : string.Join(", ", formatted);
+    }
+
+    private sealed record SpeakerSnippetResolution(
+        byte[] WavBytes,
+        string Source,
+        int SegmentCount,
+        double? Score,
+        TimeSpan Duration);
+
     private enum SpeakerIdentityProcessingMode
     {
         LiveReadOnly,