added more logging around $YESNO so we can get more consistent yes and no replies processed.... they are spotty currently

This commit is contained in:
Jacob Dubin
2026-05-03 22:42:41 -05:00
parent 2ec4902189
commit 573911de0f
8 changed files with 185 additions and 34 deletions

View File

@@ -33,6 +33,7 @@ Release `1.0.18` is now in feature-hardening. Its main bug-fix theme is alarm an
- Test 30 showed `cloud version` speaking cleanly with no interruption. The backup warning later appeared after opening gallery from the menu: gallery asked the empty-gallery photo question, then stock BE opened `@be/surprises`, selected `@be/surprises-ota`, and spoke the local backup announcement. The captured HTTP traffic still did not show hosted `Backup_*` calls.
- Test 31 sharpened the remaining alarm/back-up picture: the startup capture includes a legacy `Backup_20170222.List` request before any voice turn, the alarm set path still collapsed `7:11 AM` into `7:00 PM` / `setting alarm for seven`, and the later clock `No` replied `that's fine` before the robot opened `@be/surprises` and eventually got stuck in a blue-ring listen loop until reset.
- Test 32 shows the alarm set path is better, but two cleanup gaps remain in the newer-code window: the alarm flow can still leave a listen open at the end, and the proactive Word of the Day yes/no branch can miss a short `Yes` and bounce into a mock/echo response. The delete-alarm retry case also still asks whether to set an alarm again, then mishandles the follow-up yes/no reply.
- The websocket turn telemetry now emits compact snapshots for `binary_audio_received`, `binary_audio_ignored`, `yes_no_turn_received`, `yes_no_turn_resolved`, and `yes_no_no_input`, so the next live pass can prove whether the yes/no rule survived buffering and finalization.
- Test 30 showed the alarm value reply `638` arrived at 6:38:13 AM local. Stock clock parsed that as `6:38 PM`, and our cloud response then added a delayed `@be/clock` relaunch on top of the active local clock value flow, causing the duplicate existing-alarm replacement prompt. Current source now suppresses the extra clock relaunch for local clock follow-up rules.
- Backup-in-progress still appears robot-local in the user-facing voice flow. Tests 27, 28, 29, and 30 had no matching `Backup_*` HTTP calls during the voice prompt itself. Keep investigating robot-local scheduler/status, startup reconnect state, CPU/load, and log/upload work if backup status itself remains sluggish after surprise suppression.
- Test 26 remains the broader regression evidence for gallery success, alarm replacement/delete risk, stop/volume live proof, and short-answer STT weakness. Alarm replacement/menu agreement is still a live release risk, but Test 30 identified and patched one duplicate-handoff cause.

View File

@@ -207,6 +207,7 @@ Expected:
- no `ffmpeg` failure should become the dominant failure mode for non-Opus buffered audio
- short replies such as `yes`, `no`, `cancel`, and short alarm times should either map correctly or be classified as STT misses with evidence
- when chasing a flaky `$YESNO` reply, look for the new turn telemetry categories `binary_audio_received`, `binary_audio_ignored`, `yes_no_turn_received`, `yes_no_turn_resolved`, and `yes_no_no_input`; the useful question is whether the short reply still had `AwaitingTurnCompletion = true`, active listen rules, and buffered audio when it hit the finalizer
### Stop And Volume

View File

@@ -2,5 +2,7 @@ namespace Jibo.Cloud.Application.Abstractions;
public interface ITurnTelemetrySink
{
Task RecordTurnDiagnosticAsync(string category, IReadOnlyDictionary<string, object?> details, CancellationToken cancellationToken = default);
Task RecordTranscriptError(Exception ex, string message, CancellationToken cancellationToken = default);
}

View File

@@ -4,5 +4,7 @@ namespace Jibo.Cloud.Application.Services;
public sealed class NullTurnTelemetrySink : ITurnTelemetrySink
{
public Task RecordTurnDiagnosticAsync(string category, IReadOnlyDictionary<string, object?> details, CancellationToken cancellationToken = default) => Task.CompletedTask;
public Task RecordTranscriptError(Exception ex, string message, CancellationToken cancellationToken = default) => Task.CompletedTask;
}

View File

@@ -37,8 +37,21 @@ public sealed partial class WebSocketTurnFinalizationService(
CancellationToken cancellationToken = default)
{
var turnState = session.TurnState;
if (ShouldIgnoreLateAudio(session) || ShouldIgnoreAudioWithoutListen(turnState))
var ignoreLateAudio = ShouldIgnoreLateAudio(session);
var ignoreAudioWithoutListen = ShouldIgnoreAudioWithoutListen(turnState);
if (ignoreLateAudio || ignoreAudioWithoutListen)
{
await sink.RecordTurnDiagnosticAsync("binary_audio_ignored", BuildTurnDiagnosticSnapshot(session, envelope, new Dictionary<string, object?>
{
["ignored"] = true,
["ignoreLateAudio"] = ignoreLateAudio,
["ignoreAudioWithoutListen"] = ignoreAudioWithoutListen,
["awaitingTurnCompletion"] = turnState.AwaitingTurnCompletion,
["bufferedAudioBytes"] = turnState.BufferedAudioBytes,
["bufferedAudioChunks"] = turnState.BufferedAudioChunkCount,
["sawListen"] = turnState.SawListen,
["sawContext"] = turnState.SawContext
}), cancellationToken);
return [];
}
@@ -53,6 +66,17 @@ public sealed partial class WebSocketTurnFinalizationService(
turnState.LastAudioReceivedUtc = DateTimeOffset.UtcNow;
turnState.AwaitingTurnCompletion = true;
session.Metadata["lastAudioBytes"] = envelope.Binary?.Length ?? 0;
await sink.RecordTurnDiagnosticAsync("binary_audio_received", BuildTurnDiagnosticSnapshot(session, envelope, new Dictionary<string, object?>
{
["bufferedAudioBytes"] = turnState.BufferedAudioBytes,
["bufferedAudioChunks"] = turnState.BufferedAudioChunkCount,
["awaitingTurnCompletion"] = turnState.AwaitingTurnCompletion,
["sawListen"] = turnState.SawListen,
["sawContext"] = turnState.SawContext,
["listenRules"] = turnState.ListenRules,
["listenAsrHints"] = turnState.ListenAsrHints,
["yesNoRule"] = turnState.ListenRules.FirstOrDefault(IsConstrainedYesNoRule)
}), cancellationToken);
if (ShouldAutoFinalize(session))
{
@@ -328,6 +352,25 @@ public sealed partial class WebSocketTurnFinalizationService(
CancellationToken cancellationToken)
{
var turn = ProtocolToTurnContextMapper.MapListenMessage(envelope, session, messageType);
var turnState = session.TurnState;
if (IsYesNoTurn(turn) || ReadPrimaryYesNoRule(turn) is not null)
{
await sink.RecordTurnDiagnosticAsync("yes_no_turn_received", BuildTurnDiagnosticSnapshot(session, envelope, new Dictionary<string, object?>
{
["messageType"] = messageType,
["listenRules"] = ReadRules(turn, "listenRules").ToArray(),
["clientRules"] = ReadRules(turn, "clientRules").ToArray(),
["listenAsrHints"] = ReadRules(turn, "listenAsrHints").ToArray(),
["yesNoRule"] = ReadPrimaryYesNoRule(turn),
["awaitingTurnCompletion"] = turnState.AwaitingTurnCompletion,
["bufferedAudioBytes"] = turnState.BufferedAudioBytes,
["bufferedAudioChunks"] = turnState.BufferedAudioChunkCount,
["sawListen"] = turnState.SawListen,
["sawContext"] = turnState.SawContext,
["followUpOpen"] = session.FollowUpOpen,
["followUpExpiresUtc"] = session.FollowUpExpiresUtc
}), cancellationToken);
}
if (ShouldIgnoreBlankAudioHotphraseTurn(turn))
{
session.TurnState.AwaitingTurnCompletion = false;
@@ -366,7 +409,6 @@ public sealed partial class WebSocketTurnFinalizationService(
};
}
var turnState = session.TurnState;
if (ShouldTreatBufferedHotphraseAsGreeting(finalizedTurn, turnState, allowFallbackOnMissingTranscript))
{
finalizedTurn = WithSyntheticTranscript(finalizedTurn, "hello");
@@ -393,6 +435,22 @@ public sealed partial class WebSocketTurnFinalizationService(
if (ShouldHandleAsLocalNoInput(finalizedTurn))
{
if (IsYesNoTurn(finalizedTurn))
{
await sink.RecordTurnDiagnosticAsync("yes_no_no_input", BuildTurnDiagnosticSnapshot(session, envelope, new Dictionary<string, object?>
{
["messageType"] = messageType,
["listenRules"] = ReadRules(finalizedTurn, "listenRules").ToArray(),
["clientRules"] = ReadRules(finalizedTurn, "clientRules").ToArray(),
["listenAsrHints"] = ReadRules(finalizedTurn, "listenAsrHints").ToArray(),
["awaitingTurnCompletion"] = turnState.AwaitingTurnCompletion,
["bufferedAudioBytes"] = turnState.BufferedAudioBytes,
["bufferedAudioChunks"] = turnState.BufferedAudioChunkCount,
["sawListen"] = turnState.SawListen,
["sawContext"] = turnState.SawContext,
["followUpOpen"] = session.FollowUpOpen
}), cancellationToken);
}
turnState.AwaitingTurnCompletion = false;
session.LastTranscript = string.Empty;
session.LastIntent = null;
@@ -522,6 +580,24 @@ public sealed partial class WebSocketTurnFinalizationService(
DelayMs = map.DelayMs
}).ToArray();
if (IsYesNoTurn(finalizedTurn))
{
await sink.RecordTurnDiagnosticAsync("yes_no_turn_resolved", BuildTurnDiagnosticSnapshot(session, envelope, new Dictionary<string, object?>
{
["messageType"] = messageType,
["transcript"] = finalizedTurn.NormalizedTranscript ?? finalizedTurn.RawTranscript,
["intent"] = plan.IntentName,
["listenRules"] = ReadRules(finalizedTurn, "listenRules").ToArray(),
["clientRules"] = ReadRules(finalizedTurn, "clientRules").ToArray(),
["listenAsrHints"] = ReadRules(finalizedTurn, "listenAsrHints").ToArray(),
["awaitingTurnCompletion"] = turnState.AwaitingTurnCompletion,
["bufferedAudioBytes"] = turnState.BufferedAudioBytes,
["bufferedAudioChunks"] = turnState.BufferedAudioChunkCount,
["followUpOpen"] = session.FollowUpOpen,
["followUpExpiresUtc"] = session.FollowUpExpiresUtc
}), cancellationToken);
}
ResetBufferedAudio(session);
turnState.SawListen = false;
turnState.SawContext = false;
@@ -1045,6 +1121,25 @@ public sealed partial class WebSocketTurnFinalizationService(
.Any(static rule => string.Equals(rule, "launch", StringComparison.OrdinalIgnoreCase));
}
private static Dictionary<string, object?> BuildTurnDiagnosticSnapshot(
CloudSession session,
WebSocketMessageEnvelope envelope,
Dictionary<string, object?> details)
{
details["sessionToken"] = session.Token;
details["hostName"] = envelope.HostName;
details["path"] = envelope.Path;
details["kind"] = envelope.Kind;
details["transID"] = session.TurnState.TransId ?? session.LastTransId;
details["lastMessageType"] = session.LastMessageType;
details["awaitingTurnCompletion"] = session.TurnState.AwaitingTurnCompletion;
details["bufferedAudioBytes"] = session.TurnState.BufferedAudioBytes;
details["bufferedAudioChunks"] = session.TurnState.BufferedAudioChunkCount;
details["sawListen"] = session.TurnState.SawListen;
details["sawContext"] = session.TurnState.SawContext;
return details;
}
private static TurnContext WithSyntheticTranscript(TurnContext turn, string transcript)
{
var attributes = new Dictionary<string, object?>(turn.Attributes, StringComparer.OrdinalIgnoreCase)

View File

@@ -15,6 +15,20 @@ public sealed class FileTurnTelemetrySink(ILogger<FileTurnTelemetrySink> logger,
private readonly SemaphoreSlim _writeLock = new(1, 1);
public async Task RecordTurnDiagnosticAsync(string category, IReadOnlyDictionary<string, object?> details, CancellationToken cancellationToken = default)
{
if (!options.Value.Enabled)
{
return;
}
await WriteEventAsync(new
{
Type = category,
Details = details
}, "Turn telemetry diagnostic", LogLevel.Information, cancellationToken);
}
public async Task RecordTranscriptError(Exception ex, string message, CancellationToken cancellationToken = default)
{
if (!options.Value.Enabled)
@@ -22,15 +36,20 @@ public sealed class FileTurnTelemetrySink(ILogger<FileTurnTelemetrySink> logger,
return;
}
await WriteErrorAsync(ex, message, cancellationToken);
await WriteEventAsync(new
{
Exception = ex.ToString(),
Message = message,
Type = "transcript_error"
}, "Turn telemetry error", LogLevel.Error, cancellationToken);
}
private async Task WriteErrorAsync(Exception ex, string message, CancellationToken cancellationToken)
private async Task WriteEventAsync(object payload, string logMessage, LogLevel level, CancellationToken cancellationToken)
{
var directory = GetBaseDirectory();
Directory.CreateDirectory(directory);
var filePath = Path.Combine(directory, $"{DateTimeOffset.UtcNow:yyyyMMdd}.events.ndjson");
var line = JsonSerializer.Serialize(new { Exception = ex.ToString(), Message = message }, JsonOptions) + Environment.NewLine;
var line = JsonSerializer.Serialize(payload, JsonOptions) + Environment.NewLine;
await _writeLock.WaitAsync(cancellationToken);
try
@@ -42,7 +61,7 @@ public sealed class FileTurnTelemetrySink(ILogger<FileTurnTelemetrySink> logger,
_writeLock.Release();
}
logger.LogError("Turn telemetry Message={Message} Exception={Exception}", message, ex);
logger.Log(level, "{LogMessage} {Payload}", logMessage, payload);
}
private string GetBaseDirectory()

View File

@@ -1,13 +1,44 @@
using System.Text.Json;
using Jibo.Cloud.Application.Abstractions;
using Jibo.Cloud.Application.Services;
using Jibo.Cloud.Domain.Models;
using Jibo.Cloud.Infrastructure.Telemetry;
using Jibo.Runtime.Abstractions;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;
using Moq;
namespace Jibo.Cloud.Tests.Turn;
public sealed class FileTurnTelemetrySinkTests
{
[Fact]
public async Task RecordsTurnDiagnosticSnapshot()
{
var directoryPath = Path.Combine(Path.GetTempPath(), "OpenJibo.Tests", Guid.NewGuid().ToString("N"));
var sink = new FileTurnTelemetrySink(
NullLogger<FileTurnTelemetrySink>.Instance,
Options.Create(new TurnTelemetryOptions
{
Enabled = true,
DirectoryPath = directoryPath
}));
await sink.RecordTurnDiagnosticAsync("yes_no_turn_received", new Dictionary<string, object?>
{
["transID"] = "trans-1",
["bufferedAudioBytes"] = 1234,
["listenRules"] = new[] { "shared/yes_no", "globals/gui_nav" },
["awaitingTurnCompletion"] = true
});
var filePath = Directory.GetFiles(directoryPath, "*.events.ndjson").Single();
var payload = JsonDocument.Parse(await File.ReadAllTextAsync(filePath)).RootElement;
Assert.Equal("yes_no_turn_received", payload.GetProperty("type").GetString());
Assert.Equal("trans-1", payload.GetProperty("details").GetProperty("transID").GetString());
Assert.Equal(1234, payload.GetProperty("details").GetProperty("bufferedAudioBytes").GetInt32());
}
[Fact]
public async Task RecordsTranscriptErrorOnTurnError()
{

View File

@@ -85,7 +85,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "yeah",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "create/is_it_a_keeper" }
["listenRules"] = (string[])["create/is_it_a_keeper"]
}
});
@@ -104,8 +104,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "no",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "surprises-ota/want_to_download_now" },
["listenAsrHints"] = new[] { "$YESNO" }
["listenRules"] = (string[])["surprises-ota/want_to_download_now"],
["listenAsrHints"] = (string[])["$YESNO"]
}
});
@@ -124,8 +124,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "yes",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "shared/yes_no", "globals/gui_nav" },
["listenAsrHints"] = new[] { "$YESNO" }
["listenRules"] = (string[])["shared/yes_no", "globals/gui_nav"],
["listenAsrHints"] = (string[])["$YESNO"]
}
});
@@ -144,8 +144,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "yes",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "clock/alarm_timer_change", "globals/gui_nav" },
["listenAsrHints"] = new[] { "$YESNO" }
["listenRules"] = (string[])["clock/alarm_timer_change", "globals/gui_nav"],
["listenAsrHints"] = (string[])["$YESNO"]
}
});
@@ -164,8 +164,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "no",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "clock/alarm_timer_none_set", "globals/global_commands_launch" },
["listenAsrHints"] = new[] { "$YESNO" }
["listenRules"] = (string[])["clock/alarm_timer_none_set", "globals/global_commands_launch"],
["listenAsrHints"] = (string[])["$YESNO"]
}
});
@@ -184,7 +184,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "No.",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "settings/download_now_later", "globals/global_commands_launch" }
["listenRules"] = (string[])["settings/download_now_later", "globals/global_commands_launch"]
}
});
@@ -203,8 +203,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "Yes!",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "surprises-date/offer_date_fact", "globals/global_commands_launch" },
["listenAsrHints"] = new[] { "$YESNO" }
["listenRules"] = (string[])["surprises-date/offer_date_fact", "globals/global_commands_launch"],
["listenAsrHints"] = (string[])["$YESNO"]
}
});
@@ -607,7 +607,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "twenty five minutes",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "clock/timer_set_value" }
["listenRules"] = (string[])["clock/timer_set_value"]
}
});
@@ -628,7 +628,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "ten twenty five",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "clock/alarm_set_value" }
["listenRules"] = (string[])["clock/alarm_set_value"]
}
});
@@ -650,7 +650,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "7, 44",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "clock/alarm_set_value" },
["listenRules"] = (string[])["clock/alarm_set_value"],
["context"] = """{"runtime":{"location":{"iso":"2026-04-26T07:43:00-05:00"}}}"""
}
});
@@ -734,7 +734,7 @@ public sealed class JiboInteractionServiceTests
{
["domain"] = "alarm"
},
["clientRules"] = new[] { "clock/clock_menu" }
["clientRules"] = (string[])["clock/clock_menu"]
}
});
@@ -756,7 +756,7 @@ public sealed class JiboInteractionServiceTests
Attributes = new Dictionary<string, object?>
{
["clientIntent"] = "cancel",
["clientRules"] = new[] { "clock/alarm_timer_query_menu" },
["clientRules"] = (string[])["clock/alarm_timer_query_menu"],
["lastClockDomain"] = "alarm"
}
});
@@ -779,7 +779,7 @@ public sealed class JiboInteractionServiceTests
Attributes = new Dictionary<string, object?>
{
["clientIntent"] = "cancel",
["clientRules"] = new[] { "clock/alarm_set_value" }
["clientRules"] = (string[])["clock/alarm_set_value"]
}
});
@@ -902,7 +902,7 @@ public sealed class JiboInteractionServiceTests
Attributes = new Dictionary<string, object?>
{
["clientIntent"] = "guess",
["clientRules"] = new[] { "word-of-the-day/puzzle" },
["clientRules"] = (string[])["word-of-the-day/puzzle"],
["clientEntities"] = JsonDocument.Parse("""{"guess":"pastoral"}""").RootElement.Clone()
}
});
@@ -922,7 +922,7 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "pastoral",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "word-of-the-day/puzzle" }
["listenRules"] = (string[])["word-of-the-day/puzzle"]
}
});
@@ -959,8 +959,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "Two.",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "word-of-the-day/puzzle" },
["listenAsrHints"] = new[] { "doodad", "pastoral", "escarpment" }
["listenRules"] = (string[])["word-of-the-day/puzzle"],
["listenAsrHints"] = (string[])["doodad", "pastoral", "escarpment"]
}
});
@@ -983,8 +983,8 @@ public sealed class JiboInteractionServiceTests
NormalizedTranscript = "Haglet.",
Attributes = new Dictionary<string, object?>
{
["listenRules"] = new[] { "word-of-the-day/puzzle" },
["listenAsrHints"] = new[] { "aglet", "hovel", "wisenheimer" }
["listenRules"] = (string[])["word-of-the-day/puzzle"],
["listenAsrHints"] = (string[])["aglet", "hovel", "wisenheimer"]
}
});