From 96553979fb2cdc2f1b8a957ae50f3fc2a21a8dee Mon Sep 17 00:00:00 2001 From: Frank Date: Mon, 19 Oct 2026 10:46:06 -0700 Subject: [PATCH] fix(dankvoice): pin thinking off in rewrite, fix silent and timeout modes Refs #32 The humanizer's raw fetch to frank-zealot omitted chat_template_kwargs.enable_thinking: false, so the Qwen35 hybrid thought instead of answering (6.9 s reasoning_content, empty content - timing out the 6 s abort; or answering "" and muting the unit). Pin the kwarg, treat empty-content-with-reasoning as failure over silence, and stop the menu's test phrase from blocking its handler. Three red-captured regressions; 26/26 green, verified red against HEAD. --- agent/extensions/dankvoice.ts | 52 +++++++++++++++++++----- omp-docs/core/dankvoice.md | 18 +++++++++ omp-docs/log.md | 13 ++++++ tests/dankvoice.bats | 75 ++++++++++++++++++++++++++++++----- 4 files changed, 137 insertions(+), 21 deletions(-) diff --git a/agent/extensions/dankvoice.ts b/agent/extensions/dankvoice.ts index 3cdfd65..269d2c5 100644 --- a/agent/extensions/dankvoice.ts +++ b/agent/extensions/dankvoice.ts @@ -576,7 +576,18 @@ export function resolveRewriter(env: NodeJS.ProcessEnv, modelsYml: string, confi return resolveTinyRewriter(modelsYml, configYml); } -/** The enhancer's rewrite step; never throws — null is its "couldn't". */ +/** + * The enhancer's rewrite step; never throws — null is its "couldn't". + * + * The `chat_template_kwargs.enable_thinking: false` field is load-bearing. + * The @tiny fleet model (frank-zealot, a Qwen35 hybrid) defaults to a + * reasoning pass that fills `reasoning_content` and leaves `content` empty. + * The harness injects this flag for the built-in vocalizer; a raw POST does + * not get it, so without it the rewrite spends its whole 6 s budget thinking + * (blowing the timeout → mechanical fallback) and, when it answers in time, + * returns an empty `content` that would mute the utterance. Measured: 6.9 s / + * empty content without the flag, 0.55 s / clean prose with it. + */ export async function rewriteForSpeech(target: RewriteTarget, text: string): Promise { try { const res = await fetch(target.chatUrl, { @@ -589,6 +600,7 @@ export async function rewriteForSpeech(target: RewriteTarget, text: string): Pro { role: "user", content: text.slice(0, REWRITE_MAX_INPUT) }, ], max_tokens: REWRITE_MAX_TOKENS, + chat_template_kwargs: { enable_thinking: false }, }), signal: AbortSignal.timeout(REWRITE_TIMEOUT_MS), }); @@ -600,20 +612,33 @@ export async function rewriteForSpeech(target: RewriteTarget, text: string): Pro const message: unknown = first.message; if (!message || typeof message !== "object" || !("content" in message)) return null; const content: unknown = message.content; - if (typeof content === "string") return content.trim(); - if (!Array.isArray(content)) return null; - const parts: string[] = []; - for (const part of content) { - if (part && typeof part === "object" && "type" in part && part.type === "text" && "text" in part && typeof part.text === "string") { - parts.push(part.text); - } + const spoken = typeof content === "string" ? content.trim() : Array.isArray(content) ? textParts(content) : null; + if (spoken === null) return null; + if (spoken === "") { + // A reasoning-only reply means the endpoint ignored the thinking-off + // flag: the prose landed in reasoning_content, not content. That is a + // failed rewrite (fall back to mechanical text), NOT the enhancer's + // legitimate "" ("nothing worth saying") — which has no reasoning. + const reasoning = "reasoning_content" in message ? message.reasoning_content : undefined; + if (typeof reasoning === "string" && reasoning.trim().length > 0) return null; } - return parts.join(" ").trim(); + return spoken; } catch { return null; } } +/** Concatenated text of a content-part array; undefined shape handled by caller. */ +function textParts(content: readonly unknown[]): string { + const parts: string[] = []; + for (const part of content) { + if (part && typeof part === "object" && "type" in part && part.type === "text" && "text" in part && typeof part.text === "string") { + parts.push(part.text); + } + } + return parts.join(" ").trim(); +} + /** The text the assistant last actually said; tool-only messages do not count. */ export function lastAssistantText(messages: readonly unknown[]): string { for (let i = messages.length - 1; i >= 0; i--) { @@ -1043,7 +1068,14 @@ export default function dankvoice(pi: ExtensionAPI) { persistSettings(ctx); return; } - await speak(ctx, `dankvoice: ${voiceLabel()} through ${cfg.player?.command ?? "no player"}, checking.`); + // Fire-and-forget on purpose: awaiting the playback chain here blocks + // the menu handler for the whole phrase and the harness reports the + // command as timed out. The point of the test is to hear it, not to + // block the menu on it. + ctx.ui.notify("dankvoice: speaking the test phrase", "info"); + void speak(ctx, `dankvoice: ${voiceLabel()} through ${cfg.player?.command ?? "no player"}, checking.`).catch((error) => + ctx.ui.notify(`dankvoice: ${error instanceof Error ? error.message : String(error)}`, "error"), + ); } pi.registerCommand("say", { diff --git a/omp-docs/core/dankvoice.md b/omp-docs/core/dankvoice.md index 0d6d568..8f2c635 100644 --- a/omp-docs/core/dankvoice.md +++ b/omp-docs/core/dankvoice.md @@ -142,6 +142,15 @@ supplies the `baseUrl`; the request is `POST {base}/chat/completions`. On this fleet that is **frank-zealot** (`llamacpp (dankclaw-3090)`, `:7771`) — the 6 s abort keeps a slow tiny model off the critical path. +The request body pins `chat_template_kwargs: { enable_thinking: false }`, +and that field is load-bearing: the harness injects it for managed roles, +but a raw `fetch` gets the model's default — thinking on — so the Qwen35 +hybrid spends the budget on `reasoning_content` and answers `content: ""` +(measured: 6.9 s / 6893 reasoning chars / empty content without the flag; +0.55 s / 369 clean chars with it). For a hybrid endpoint, empty content +beside non-empty `reasoning_content` means the flag was ignored — a failed +rewrite (mechanical fallback), never the legitimate "nothing to say". + Thinking blocks ride the same path: at `agent_end` the last assistant message's true `thinking` parts are narrated (rewritten first, as their own unit, before the answer), while blocks flagged `narration: true` — which @@ -196,6 +205,14 @@ the choice persists in the settings file. prose segments (mechanical cleanup of that text yields at most 2), and a thinking+answer `agent_end` played thinking first. 22 green in `tests/dankvoice.bats`. +* **Thinking-off fix (2026-10-19, Refs #32)** — replaying the exact rewrite + body against live frank-zealot: without `chat_template_kwargs. + enable_thinking: false` the reply arrives as 6893 `reasoning_content` + characters with `content: ""` in 6.9 s (twice the 6 s abort); with it, + 369 clean characters in 0.55 s. Driver fixtures now pin the flag + (`thinkoff=false` on the recorded chat call), turn reasoning-only replies + into mechanical speech instead of silence, and time the menu's test + phrase (~0 ms handler). 26 green in `tests/dankvoice.bats`. ## Limits @@ -232,6 +249,7 @@ the choice persists in the settings file. * Gitea issue #21 on `dank/command-center` (the work item this page ships with). * Gitea issue #23 on `dank/command-center` (the options-menu work item). * Gitea issue #27 on `dank/command-center` (the enhanced-narration work item). +* Gitea issue #32 on `dank/command-center` (the latency/silence fix work item). ## See Also diff --git a/omp-docs/log.md b/omp-docs/log.md index 98985e0..9345718 100644 --- a/omp-docs/log.md +++ b/omp-docs/log.md @@ -16,6 +16,19 @@ lesson, a few lines. Full incident narratives are recoverable from git (`git log --follow omp-docs/log.md`); knowledge that outlives an entry lives on its concept page, linked here. Never re-expand an entry in place. +## 2026-10-19 — dankvoice: silence and timeouts, root-caused (Refs #32) + +The humanizer's raw `fetch` to frank-zealot omitted `chat_template_kwargs. +enable_thinking: false`, so the Qwen35 hybrid *thought* instead of answering: +6.9 s of `reasoning_content`, `content: ""` — timing out the rewrite twice +(12 s dead air) and, when it did answer inside the window, speaking silence. +Root-caused by replaying the exact wire body against the live endpoint. +Fix: pin the kwarg in the request body; treat empty-content-with-reasoning as +failure (mechanical voice), not "nothing worth saying"; the menu's test phrase +fires without blocking its handler. Lesson: the harness injects thinking-off +for managed roles, but raw HTTP callers must set it themselves — 26/26 green +with three red-captured regressions. + ## 2026-10-19 — dankvoice: humanized narration and thinking aloud (Refs #27) Spoken units are rewritten by the `@tiny` role (frank-zealot) under the diff --git a/tests/dankvoice.bats b/tests/dankvoice.bats index 96de17e..f79749b 100755 --- a/tests/dankvoice.bats +++ b/tests/dankvoice.bats @@ -14,8 +14,9 @@ # (player fixture), DV_PWPLAY (stub aliased as pw-play), DV_WPCTL (the sink # name the fixture wpctl reports), DV_MODELS (models.yml fixture), # DANKVOICE_CONFIG (settings file), DV_PLAYER_BIN (player command override), -# DV_SELECT (pipe-separated answers fed to ctx.ui.select in order), DV_MODE -# (the harness mode reported to the extension). +# DV_MODE (the harness mode reported to the extension), DV_REWRITE (fixture +# behavior for the humanizer route: prose | echo | reasoning | stall, with +# DV_STALL_MS). setup() { REPO="$(cd "$BATS_TEST_DIRNAME/.." && pwd)" @@ -31,8 +32,10 @@ setup() { cat > "$DV_STUB" <<'SH' #!/usr/bin/env bash printf '%s\n' "$*" >> "$DV_STUB_LOG" +if [ -n "${DV_TIMING_LOG:-}" ]; then printf 'START %s\n' "$(date +%s%3N)" >> "$DV_TIMING_LOG"; fi for arg in "$@"; do case "$arg" in *.wav) cp "$arg" "$DV_COPY" ;; esac; done -sleep 0.1 +sleep "${DV_HOLD:-0.1}" +if [ -n "${DV_TIMING_LOG:-}" ]; then printf 'END %s\n' "$(date +%s%3N)" >> "$DV_TIMING_LOG"; fi SH chmod +x "$DV_STUB" @@ -84,14 +87,21 @@ import { dirname } from "node:path"; const scenario = process.argv[2] ?? "speak"; const AUDIO = Buffer.from([0x52, 0x49, 0x46, 0x46, 8, 0, 0, 0, 0x57, 0x41, 0x56, 0x45, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12]); -const received: Array<{ url: string | undefined; body: string }> = []; +const started = Date.now(); +interface Call { + url: string | undefined; + body: string; + at: number; +} +const received: Call[] = []; const server = createServer((req, res) => { const chunks: Buffer[] = []; req.on("data", (chunk: Buffer) => chunks.push(chunk)); req.on("end", () => { + const at = Date.now() - started; const body = Buffer.concat(chunks).toString("utf8"); - received.push({ url: req.url, body }); + received.push({ url: req.url, body, at }); if (req.url?.endsWith("/audio/voices")) { res.setHeader("content-type", "application/json"); res.end(JSON.stringify(["narrator1", "narrator2"])); @@ -103,11 +113,18 @@ const server = createServer((req, res) => { return; } if (process.env.DV_REWRITE && req.url?.endsWith("/chat/completions")) { - res.setHeader("content-type", "application/json"); - const spoken = process.env.DV_REWRITE === "echo" - ? String(JSON.parse(body).messages?.[1]?.content ?? "") - : "Spoken, humanized words."; - res.end(JSON.stringify({ choices: [{ message: { content: spoken } }] })); + const respond = () => { + res.setHeader("content-type", "application/json"); + const spoken = process.env.DV_REWRITE === "echo" + ? String(JSON.parse(body).messages?.[1]?.content ?? "") + : "Spoken, humanized words."; + const verdict = process.env.DV_REWRITE === "reasoning" + ? { choices: [{ message: { content: "", reasoning_content: "Long internal deliberation that never reaches the reply field." } }] } + : { choices: [{ message: { content: spoken } }] }; + res.end(JSON.stringify(verdict)); + }; + if (process.env.DV_REWRITE === "stall") setTimeout(respond, Number(process.env.DV_STALL_MS ?? 200)); + else respond(); return; } res.statusCode = 404; @@ -219,6 +236,12 @@ if (!say) { await say.handler("on", ctx); await agentEnd?.({ messages: [{ role: "assistant", content: [{ type: "thinking", thinking: "Considering the wiring." }, { type: "text", text: "The answer is nine." }] }] }, ctx); break; + case "testphrase": { + const startedAt = Date.now(); + await say.handler("menu", ctx); + console.log(`HANDLER_MS ${Date.now() - startedAt}`); + break; + } case "narration": await say.handler("on", ctx); await agentEnd?.({ messages: [{ role: "assistant", content: [{ type: "thinking", thinking: "Here is the result.", narration: true }] }] }, ctx); @@ -239,7 +262,11 @@ for (const call of received) { } return "-"; }; - console.log(`CALL ${call.url} model=${field("model")} format=${field("response_format")} voice=${field("voice")} input=${field("input")}`); + const kwargs = parsed && typeof parsed === "object" && "chat_template_kwargs" in parsed + ? (parsed as { chat_template_kwargs?: { enable_thinking?: unknown } }).chat_template_kwargs + : undefined; + const think = kwargs && typeof kwargs === "object" && "enable_thinking" in kwargs ? String(kwargs.enable_thinking) : "absent"; + console.log(`CALL ${call.url} model=${field("model")} format=${field("response_format")} voice=${field("voice")} input=${field("input")}${call.url?.endsWith("/chat/completions") ? ` thinkoff=${think}` : ""}`); } console.log(`CALLS ${received.filter((call) => call.url?.endsWith("/audio/speech")).length}`); const log = process.env.DV_STUB_LOG && existsSync(process.env.DV_STUB_LOG) ? readFileSync(process.env.DV_STUB_LOG, "utf8").trim() : ""; @@ -417,3 +444,29 @@ say_run() { DV_PLAYER_BIN="$DV_PWPLAY" say_run speak [[ "$output" == *"PLAYER --target $DV_WPCTL"* ]] } + +@test "the rewrite asks the humanizer with thinking explicitly off" { + DV_REWRITE=prose say_run rewrite + [[ "$output" == *"input=- thinkoff=false"* ]] +} + +@test "an answer hiding in reasoning_content speaks the mechanical text, not silence" { + DV_REWRITE=reasoning say_run rewrite + [[ "$output" == *"input=The deploy failed because a secret was missing."* ]] + [[ "$output" == *"CALLS 1"* ]] + [[ "$output" == *"PLAYS 1"* ]] +} + +@test "a rewrite slower than a breath but under the timeout still speaks" { + DV_REWRITE=stall DV_STALL_MS=300 say_run rewrite + [[ "$output" == *"input=Spoken, humanized words."* ]] + [[ "$output" == *"CALLS 1"* ]] +} + +@test "the menu test phrase speaks in the background instead of blocking the menu" { + DV_REWRITE=stall DV_STALL_MS=1500 say_run testphrase "Speak a test phrase" + [[ "$output" == *"NOTIFY info dankvoice: speaking the test phrase"* ]] + local ms + ms=$(grep -o 'HANDLER_MS [0-9]*' <<<"$output" | cut -d' ' -f2) + [ -n "$ms" ] && [ "$ms" -lt 1200 ] +} -- 2.54.0